reduce log level in metrics logger not to trash the log #708

nirrozenbaum · 2025-04-17T21:14:25Z

metrics logger is trashing the epp log. so instead of allowing a focused view of what changed, the epp log looks like this:

{"level":"Level(-3)","ts":"2025-04-17T21:04:48Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:04:53Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:04:58Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:03Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:08Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"info","ts":"2025-04-17T21:05:10Z","caller":"runnable/grpc.go:19","msg":"gRPC server starting","name":"ext-proc"}
{"level":"info","ts":"2025-04-17T21:05:10Z","caller":"runnable/grpc.go:28","msg":"gRPC server listening","name":"ext-proc","port":9002}
{"level":"Level(-3)","ts":"2025-04-17T21:05:13Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:18Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:23Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:28Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:33Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:38Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:43Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:48Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:53Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:05:58Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:03Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:08Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:13Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:18Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:23Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:28Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:33Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:38Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:43Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:48Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:53Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:06:58Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:03Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:08Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:13Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:18Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:23Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:28Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:33Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:38Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:43Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:48Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:53Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:07:58Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:03Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:08Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:13Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:18Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:23Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:28Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}
{"level":"Level(-3)","ts":"2025-04-17T21:08:33Z","caller":"metrics/logger.go:101","msg":"Flushing Prometheus Metrics","ReadyPods":1}

since EPP default log level is 4, this PR reduces the log level of the metrics logger (only this specific message) to TRACE to reduce this noise in the log.

additionally, as a followup to previous PR, change in few more places to use NamespacedName instead of passing around name + namespace as separate args.

Signed-off-by: Nir Rozenbaum <[email protected]>

nirrozenbaum · 2025-04-17T21:14:50Z

cc @kfswain

netlify · 2025-04-17T21:14:52Z

✅ Deploy Preview for gateway-api-inference-extension ready!

Name	Link
🔨 Latest commit	`c9a456f`
🔍 Latest deploy log	https://app.netlify.com/sites/gateway-api-inference-extension/deploys/6803d7f5dcb8890008b69079
😎 Deploy Preview	https://deploy-preview-708--gateway-api-inference-extension.netlify.app
📱 Preview on mobile	Toggle QR Code... Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify site configuration.

danehans · 2025-04-17T23:42:07Z

+1 on changing the log level to DEBUG. Additionally, pool in the following log message should be capitalized:

logger.V(logutil.DEFAULT).Info("pool is not initialized, skipping flushing metrics")

In reviewing flushPrometheusMetricsOnce(), the Pod metrics are not being "flushed" but are instead being "Regenerated", "Recalculated", etc. We should consider renaming the function and the associated log message.

Signed-off-by: Nir Rozenbaum <[email protected]>

nirrozenbaum · 2025-04-18T06:29:26Z

+1 on changing the log level to DEBUG. Additionally, pool in the following log message should be capitalized:
logger.V(logutil.DEFAULT).Info("pool is not initialized, skipping flushing metrics")
In reviewing flushPrometheusMetricsOnce(), the Pod metrics are not being "flushed" but are instead being "Regenerated", "Recalculated", etc. We should consider renaming the function and the associated log message.

@danehans updated the log level and capitalized log message.
as for the function name, I updated it to refreshPrometheusMetrics to stay aligned with the terminology used in the code (the cmd-ling flag is called refreshPrometheusMetricsInterval, the function arg is called refreshPrometheusMetricsInterval, default value is defined in runserver.DefaultRefreshPrometheusMetricsInterval, etc)

ahg-g · 2025-04-18T18:13:14Z

pkg/epp/backend/metrics/logger.go

 		return
 	}

 	var kvCacheTotal float64
 	var queueTotal int

 	podMetrics := datastore.PodGetAll()
-	logger.V(logutil.VERBOSE).Info("Flushing Prometheus Metrics", "ReadyPods", len(podMetrics))
+	logger.V(logutil.TRACE).Info("Refreshing Prometheus Metrics", "ReadyPods", len(podMetrics))


Is there an alternative log in verbose or default level that logs the number of ready pods when they change?

I haven't seen any other place logging the ready pods (it's reported as a metric though).
I completely agree this is information we would like to know.

having said that, I don't think it belongs here.
the refreshMetrics function runs every few seconds to update metrics, which makes perfect sense since we would like to update metrics very frequently.
BUT, printing to the EPP log the number of ready pods every 5 seconds is spamming the log and making it very hard to debug (see example above).

IMO the number of pods in the pool shouldn't be printed as part of metrics recalculation function, it should be part of the Inf Pool status (kinda similar to ready pods status in deployment).
we could easily add this field to Inf Pool status + additional printer columns to show it when running kubectl get InferencePool. it's pretty easy to implement in the controllers reconcile event which also updates only when something changes (as opposed to this log printing, which happens every 5 seconds even if nothing has changed).
If this sounds reasonable I'm happy to implement it this week.

@ahg-g cc @kfswain

proposed this change in #714

pkg/epp/backend/metrics/logger.go

Signed-off-by: Nir Rozenbaum <[email protected]>

kfswain · 2025-04-23T01:06:22Z

This LGTM, a dev can up the log level or adjust the image they are working on, ops probably doesnt need this spammed.

Is there an alternative log in verbose or default level that logs the number of ready pods when they change?
This is reasonable but can be resolved outside this PR I think

/lgtm
/approve

k8s-ci-robot · 2025-04-23T01:06:29Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: kfswain, nirrozenbaum

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:

~~OWNERS~~ [kfswain]

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

…igs#708) * reduce log level in metrics logger not to trash the log Signed-off-by: Nir Rozenbaum <[email protected]> * rename flush metrics to refresh metrics Signed-off-by: Nir Rozenbaum <[email protected]> * revert log level Signed-off-by: Nir Rozenbaum <[email protected]> --------- Signed-off-by: Nir Rozenbaum <[email protected]>

* Add unit test coverage for pod APIs under datastore/pkg * Add unit test coverage for pod APIs under datastore/pkg * Add unit test coverage for pod APIs under datastore/pkg * Add unit test coverage for pod APIs under datastore/pkg * EPP Architecture proposal (#683) * initial changes * Adding to proposal to give a quick barebones definition to refactor * feedback changes * more feedback addressing * removed unused Fake struct (#723) Signed-off-by: Nir Rozenbaum <[email protected]> * epp: return correct response for trailers (#726) This looks like a copy paste error. * Refactor scheduler to run plugins (#677) * Refactor scheduler to run plugins * Add scheduler plugin latency metric * Address comments * Address comments * Complete the InferencePool documentation (#673) * Initial guide for inference pool * Add extensionReference to the InferencePool spec * Fix list formatting * Remove unused labels * Autogenerate the spec * Update site-src/api-types/inferencepool.md Co-authored-by: Rob Scott <[email protected]> * Update site-src/api-types/inferencepool.md Co-authored-by: Rob Scott <[email protected]> * Update site-src/api-types/inferencepool.md Co-authored-by: Rob Scott <[email protected]> * Update site-src/api-types/inferencepool.md Co-authored-by: Rob Scott <[email protected]> * Update site-src/api-types/inferencepool.md Co-authored-by: Rob Scott <[email protected]> * Update site-src/api-types/inferencepool.md Co-authored-by: Rob Scott <[email protected]> * Rename llm-pool names in rollout example * Add use cases for replacing an inference pool * Rewording the background section * Create replacing-inference-pool.md * Replace instructions with a link for how to replace an inference pool * Update replacing-inference-pool.md * Update mkdocs.yml * Update replacing-inference-pool.md * Update inferencemodel_types.go * Update inferencepool.md * Update site-src/guides/replacing-inference-pool.md Co-authored-by: Rob Scott <[email protected]> --------- Co-authored-by: Rob Scott <[email protected]> * reduce log level in metrics logger not to trash the log (#708) * reduce log level in metrics logger not to trash the log Signed-off-by: Nir Rozenbaum <[email protected]> * rename flush metrics to refresh metrics Signed-off-by: Nir Rozenbaum <[email protected]> * revert log level Signed-off-by: Nir Rozenbaum <[email protected]> --------- Signed-off-by: Nir Rozenbaum <[email protected]> * few updates in datastore (#713) * few updates in datastore Signed-off-by: Nir Rozenbaum <[email protected]> * PoolSet documentation Signed-off-by: Nir Rozenbaum <[email protected]> * error phrasing Signed-off-by: Nir Rozenbaum <[email protected]> * removed unused pool arg from PodUpdateOrAddIfNotExist Signed-off-by: Nir Rozenbaum <[email protected]> * linter Signed-off-by: Nir Rozenbaum <[email protected]> --------- Signed-off-by: Nir Rozenbaum <[email protected]> * scheduler refactoring (#730) Signed-off-by: Nir Rozenbaum <[email protected]> * filter irrelevant pod in pod_reconciler (#696) * EPP: Update GetRandomPod() to return nil if no pods exist (#731) Signed-off-by: Daneyon Hansen <[email protected]> * Move filter and scorer plugins registration to a separate file (#729) * Move filters and scorers registration to filter/scorer specific files * Default scheduler config contains empty list of scorers Signed-off-by: Maya Barnea <[email protected]> * Default plugin is not a scorer any more Signed-off-by: Maya Barnea <[email protected]> * fix scheduler test + lint comments Signed-off-by: Maya Barnea <[email protected]> --------- Signed-off-by: Maya Barnea <[email protected]> * Update issue templates (#738) * Update issue templates * Updates artifacts for v0.3.0-rc.1 release Signed-off-by: Kellen Swain <[email protected]> * Updates bbr chart for v0.3.0-rc.1 release Signed-off-by: Kellen Swain <[email protected]> * Updates artifacts for v0.3.0 release Signed-off-by: Kellen Swain <[email protected]> * Adding blank issue template so that all issues start with label --------- Signed-off-by: Kellen Swain <[email protected]> * Add unit test coverage for pod APIs under datastore/pkg * few updates in datastore (#713) * few updates in datastore Signed-off-by: Nir Rozenbaum <[email protected]> * PoolSet documentation Signed-off-by: Nir Rozenbaum <[email protected]> * error phrasing Signed-off-by: Nir Rozenbaum <[email protected]> * removed unused pool arg from PodUpdateOrAddIfNotExist Signed-off-by: Nir Rozenbaum <[email protected]> * linter Signed-off-by: Nir Rozenbaum <[email protected]> --------- Signed-off-by: Nir Rozenbaum <[email protected]> * few updates in datastore (#713) * few updates in datastore Signed-off-by: Nir Rozenbaum <[email protected]> * PoolSet documentation Signed-off-by: Nir Rozenbaum <[email protected]> * error phrasing Signed-off-by: Nir Rozenbaum <[email protected]> * removed unused pool arg from PodUpdateOrAddIfNotExist Signed-off-by: Nir Rozenbaum <[email protected]> * linter Signed-off-by: Nir Rozenbaum <[email protected]> --------- Signed-off-by: Nir Rozenbaum <[email protected]> * Add unit test coverage for pod APIs under datastore/pkg --------- Signed-off-by: Nir Rozenbaum <[email protected]> Signed-off-by: Daneyon Hansen <[email protected]> Signed-off-by: Maya Barnea <[email protected]> Signed-off-by: Kellen Swain <[email protected]> Co-authored-by: Kellen Swain <[email protected]> Co-authored-by: Nir Rozenbaum <[email protected]> Co-authored-by: John Howard <[email protected]> Co-authored-by: Cong Liu <[email protected]> Co-authored-by: Nicole Xin <[email protected]> Co-authored-by: Rob Scott <[email protected]> Co-authored-by: nayihz <[email protected]> Co-authored-by: Daneyon Hansen <[email protected]> Co-authored-by: Maya Barnea <[email protected]>

reduce log level in metrics logger not to trash the log

65fa1ab

Signed-off-by: Nir Rozenbaum <[email protected]>

k8s-ci-robot added the cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. label Apr 17, 2025

k8s-ci-robot requested review from ahg-g and robscott April 17, 2025 21:14

k8s-ci-robot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Apr 17, 2025

rename flush metrics to refresh metrics

ce10701

Signed-off-by: Nir Rozenbaum <[email protected]>

ahg-g reviewed Apr 18, 2025

View reviewed changes

revert log level

c9a456f

Signed-off-by: Nir Rozenbaum <[email protected]>

k8s-ci-robot assigned kfswain Apr 23, 2025

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Apr 23, 2025

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Apr 23, 2025

k8s-ci-robot merged commit f1d425b into kubernetes-sigs:main Apr 23, 2025
8 checks passed

nirrozenbaum deleted the trashedlog branch April 23, 2025 03:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

reduce log level in metrics logger not to trash the log #708

reduce log level in metrics logger not to trash the log #708

nirrozenbaum commented Apr 17, 2025

nirrozenbaum commented Apr 17, 2025

netlify bot commented Apr 17, 2025 •

edited

Loading

danehans commented Apr 17, 2025

nirrozenbaum commented Apr 18, 2025

ahg-g Apr 18, 2025

nirrozenbaum Apr 19, 2025 •

edited

Loading

nirrozenbaum Apr 19, 2025

kfswain commented Apr 23, 2025

k8s-ci-robot commented Apr 23, 2025

reduce log level in metrics logger not to trash the log #708

reduce log level in metrics logger not to trash the log #708

Conversation

nirrozenbaum commented Apr 17, 2025

nirrozenbaum commented Apr 17, 2025

netlify bot commented Apr 17, 2025 • edited Loading

✅ Deploy Preview for gateway-api-inference-extension ready!

danehans commented Apr 17, 2025

nirrozenbaum commented Apr 18, 2025

ahg-g Apr 18, 2025

Choose a reason for hiding this comment

nirrozenbaum Apr 19, 2025 • edited Loading

Choose a reason for hiding this comment

nirrozenbaum Apr 19, 2025

Choose a reason for hiding this comment

kfswain commented Apr 23, 2025

k8s-ci-robot commented Apr 23, 2025

netlify bot commented Apr 17, 2025 •

edited

Loading

nirrozenbaum Apr 19, 2025 •

edited

Loading