diff --git a/pkg/epp/scheduling/framework/scheduler_profile.go b/pkg/epp/scheduling/framework/scheduler_profile.go index 9c0ae0abc..db547088a 100644 --- a/pkg/epp/scheduling/framework/scheduler_profile.go +++ b/pkg/epp/scheduling/framework/scheduler_profile.go @@ -128,21 +128,21 @@ func (p *SchedulerProfile) Run(ctx context.Context, request *types.LLMRequest, c } func (p *SchedulerProfile) runFilterPlugins(ctx context.Context, request *types.LLMRequest, cycleState *types.CycleState, pods []types.Pod) []types.Pod { - loggerDebug := log.FromContext(ctx).V(logutil.DEBUG) + logger := log.FromContext(ctx) filteredPods := pods - loggerDebug.Info("Before running filter plugins", "pods", filteredPods) + logger.V(logutil.DEBUG).Info("Before running filter plugins", "pods", filteredPods) for _, filter := range p.filters { - loggerDebug.Info("Running filter plugin", "plugin", filter.TypedName()) + logger.V(logutil.VERBOSE).Info("Running filter plugin", "plugin", filter.TypedName()) before := time.Now() filteredPods = filter.Filter(ctx, cycleState, request, filteredPods) metrics.RecordPluginProcessingLatency(FilterExtensionPoint, filter.TypedName().Type, filter.TypedName().Name, time.Since(before)) - loggerDebug.Info("Completed running filter plugin successfully", "plugin", filter.TypedName(), "pods", filteredPods) + logger.V(logutil.DEBUG).Info("Completed running filter plugin successfully", "plugin", filter.TypedName(), "pods", filteredPods) if len(filteredPods) == 0 { break } } - loggerDebug.Info("Completed running filter plugins successfully") + logger.V(logutil.VERBOSE).Info("Completed running filter plugins successfully") return filteredPods } @@ -157,7 +157,7 @@ func (p *SchedulerProfile) runScorerPlugins(ctx context.Context, request *types. } // Iterate through each scorer in the chain and accumulate the weighted scores. for _, scorer := range p.scorers { - logger.V(logutil.DEBUG).Info("Running scorer plugin", "plugin", scorer.TypedName()) + logger.V(logutil.VERBOSE).Info("Running scorer plugin", "plugin", scorer.TypedName()) before := time.Now() scores := scorer.Score(ctx, cycleState, request, pods) metrics.RecordPluginProcessingLatency(ScorerExtensionPoint, scorer.TypedName().Type, scorer.TypedName().Name, time.Since(before)) @@ -167,25 +167,25 @@ func (p *SchedulerProfile) runScorerPlugins(ctx context.Context, request *types. } logger.V(logutil.DEBUG).Info("Completed running scorer plugin successfully", "plugin", scorer.TypedName()) } - logger.V(logutil.DEBUG).Info("Completed running scorer plugins successfully") + logger.V(logutil.VERBOSE).Info("Completed running scorer plugins successfully") return weightedScorePerPod } func (p *SchedulerProfile) runPickerPlugin(ctx context.Context, cycleState *types.CycleState, weightedScorePerPod map[types.Pod]float64) *types.ProfileRunResult { - loggerDebug := log.FromContext(ctx).V(logutil.DEBUG) + logger := log.FromContext(ctx) scoredPods := make([]*types.ScoredPod, len(weightedScorePerPod)) i := 0 for pod, score := range weightedScorePerPod { scoredPods[i] = &types.ScoredPod{Pod: pod, Score: score} i++ } - - loggerDebug.Info("Running picker plugin", "plugin", p.picker.TypedName(), "pods-weighted-score", weightedScorePerPod) + logger.V(logutil.VERBOSE).Info("Running picker plugin", "plugin", p.picker.TypedName()) + logger.V(logutil.DEBUG).Info("Candidate pods for picking", "pods-weighted-score", scoredPods) before := time.Now() result := p.picker.Pick(ctx, cycleState, scoredPods) metrics.RecordPluginProcessingLatency(PickerExtensionPoint, p.picker.TypedName().Type, p.picker.TypedName().Name, time.Since(before)) - loggerDebug.Info("Completed running picker plugin successfully", "plugin", p.picker.TypedName(), "result", result) + logger.V(logutil.DEBUG).Info("Completed running picker plugin successfully", "plugin", p.picker.TypedName(), "result", result) return result } diff --git a/pkg/epp/scheduling/scheduler.go b/pkg/epp/scheduling/scheduler.go index 12c18833a..d7bcb1f27 100644 --- a/pkg/epp/scheduling/scheduler.go +++ b/pkg/epp/scheduling/scheduler.go @@ -45,8 +45,7 @@ type Scheduler struct { // Schedule finds the target pod based on metrics and the requested lora adapter. func (s *Scheduler) Schedule(ctx context.Context, request *types.LLMRequest, candidatePods []types.Pod) (*types.SchedulingResult, error) { - logger := log.FromContext(ctx).WithValues("requestId", request.RequestId, "targetModel", request.TargetModel) - loggerDebug := logger.V(logutil.DEBUG) + loggerVerbose := log.FromContext(ctx).V(logutil.VERBOSE) scheduleStart := time.Now() defer func() { @@ -57,23 +56,23 @@ func (s *Scheduler) Schedule(ctx context.Context, request *types.LLMRequest, can cycleState := types.NewCycleState() for { // get the next set of profiles to run iteratively based on the request and the previous execution results - loggerDebug.Info("Running profile handler, Pick profiles", "plugin", s.profileHandler.TypedName()) + loggerVerbose.Info("Running profile handler, Pick profiles", "plugin", s.profileHandler.TypedName()) before := time.Now() profiles := s.profileHandler.Pick(ctx, cycleState, request, s.profiles, profileRunResults) metrics.RecordPluginProcessingLatency(framework.ProfilePickerExtensionPoint, s.profileHandler.TypedName().Type, s.profileHandler.TypedName().Name, time.Since(before)) - loggerDebug.Info("Completed running profile handler Pick profiles successfully", "plugin", s.profileHandler.TypedName(), "result", profiles) + loggerVerbose.Info("Completed running profile handler Pick profiles successfully", "plugin", s.profileHandler.TypedName(), "result", profiles) if len(profiles) == 0 { // profile picker didn't pick any profile to run break } for name, profile := range profiles { - loggerDebug.Info("Running scheduler profile", "name", name) + loggerVerbose.Info("Running scheduler profile", "profile", name) // run the selected profiles and collect results (current code runs all profiles) profileRunResult, err := profile.Run(ctx, request, cycleState, candidatePods) if err != nil { - loggerDebug.Info("failed to run scheduler profile", "profile", name, "error", err.Error()) + loggerVerbose.Info("failed to run scheduler profile", "profile", name, "error", err.Error()) } else { - loggerDebug.Info("Completed running scheduler profile succuessfully", "name", name) + loggerVerbose.Info("Completed running scheduler profile succuessfully", "profile", name) } profileRunResults[name] = profileRunResult // if profile failed to run, the run result is nil @@ -84,11 +83,11 @@ func (s *Scheduler) Schedule(ctx context.Context, request *types.LLMRequest, can return nil, fmt.Errorf("failed to run any scheduler profile for request %s", request.RequestId) } - loggerDebug.Info("Running profile handler, ProcessResults", "plugin", s.profileHandler.TypedName()) + loggerVerbose.Info("Running profile handler, ProcessResults", "plugin", s.profileHandler.TypedName()) before := time.Now() result, err := s.profileHandler.ProcessResults(ctx, cycleState, request, profileRunResults) metrics.RecordPluginProcessingLatency(framework.ProcessProfilesResultsExtensionPoint, s.profileHandler.TypedName().Type, s.profileHandler.TypedName().Name, time.Since(before)) - loggerDebug.Info("Completed running profile handler ProcessResults successfully", "plugin", s.profileHandler.TypedName()) + loggerVerbose.Info("Completed running profile handler ProcessResults successfully", "plugin", s.profileHandler.TypedName()) return result, err }