Reduce log volume#6568
Open
PSeitz-dd wants to merge 7 commits into
Open
Conversation
The rate-limited tracing macros emitted a separate "suppressed N similar log messages" line before the next allowed line. Attach the count to that line instead, as a `suppressed_in_last_min` field. This makes the suppression rate visible inline on the message it belongs to and removes a distinct log pattern, slightly lowering volume.
…EM-759) A fleet-wide extract showed ~1.07B log lines, dominated by a single per-gossip-tick INFO (~907M, ~85%). Reclassify high-frequency operational logs to cut default-level volume by ~20x while preserving actionable signal: - INFO -> DEBUG for routine per-operation chatter with no liveness value: node pool-add (x4), send-to-index-serializer, spawning pipeline, merge schedule/download, leaf split-finished/offsets, offload-to-lambda, resetting pipeline, adding shards assignment. - INFO -> rate-limited INFO (1/min) for logs worth a heartbeat: new-split, actor-exit (success), assigning shards, env-var defaults, truncated-shard. - ERROR -> rate-limited ERROR (1/min) for the recurring lambda invocation failure, keeping it visible without flooding. Error/failure branches are untouched (e.g. actor-exit failure stays at ERROR). Stage/publish, merge-completion, and cluster lifecycle stay at INFO.
The publish-new-splits log carried no fields. Add num_splits, num_docs, and total on-disk split size to give operators visibility into publish throughput and split sizing without adding a new log line. num_splits is >1 only for partitioned sources (a single commit produces one split per partition); merges publish a single output split, with the merged inputs recorded in replaced_split_ids.
This is a low-volume (~80K), operationally meaningful event: the searcher spilling search work to Lambda. It carries capacity/cost signal and pairs with the lambda invocation error we deliberately keep visible. Demoting it to DEBUG bought no real volume reduction, so revert it to INFO.
Keep visibility into ingester, searcher, and generic-service pool membership at INFO but cap each to 1/min. These are far lower volume than the indexer pool-add (~907M), which stays at DEBUG.
…uppressed Rate-limit the indexer pool-add log (~907M, the dominant pattern) at INFO 1/min instead of demoting to DEBUG. At 1/min this collapses to ~1.4K/day -- the same volume win as DEBUG -- while keeping pool membership visible at INFO, consistent with the other three pool-add logs. Rename the rate-limit suppressed-count field from `suppressed_in_last_min` to `num_suppressed`: the count is messages suppressed since the call site last emitted, and since the window only resets on the next call it can span more than a minute, so the old name was misleading.
PSeitz
changed the title
fulmicoton
reviewed
Jul 1, 2026
| flag_value | ||
| } else { | ||
| info!(default_value=%default_value, "using environment variable `{key}` default value"); | ||
| crate::rate_limited_info!(limit_per_min = 1, default_value=%default_value, "using environment variable `{key}` default value"); |
Contributor
Author
There was a problem hiding this comment.
we have ~2M logs of that in the last week on the hooray cluster. I'll try to find the call sites and cache them instead of rate-limiting
Contributor
Author
There was a problem hiding this comment.
Added caching to the callsites (with some macro to avoid misuse in the future)
fulmicoton
reviewed
Jul 1, 2026
| | ActorExitStatus::DownstreamClosed | ||
| | ActorExitStatus::Killed => { | ||
| info!(actor_id, phase = ?exit_phase, exit_status = ?after_process_exit_status, "actor-exit"); | ||
| quickwit_common::rate_limited_info!(limit_per_min = 1, actor_id, phase = ?exit_phase, exit_status = ?after_process_exit_status, "actor-exit"); |
Collaborator
There was a problem hiding this comment.
I don't think we want to rate limit this one
Contributor
Author
There was a problem hiding this comment.
I can remove it, but we had ~4M log lines of that in the last week
Contributor
Author
There was a problem hiding this comment.
Removed the rate limiting
Collaborator
|
I am all for reducing logging but this is a terrible PR! |
The "using environment variable ... default value" INFO lines flooded because callers like PostgresqlMetastore::new read the same variables on every (re)construction, and the metastore is rebuilt frequently. Rate- limiting the shared log statement (previous approach) funneled every key through one call-site counter, so within a burst only the first key was ever logged and the rest were deterministically dropped. Instead, add per-call-site caching macros in quickwit-common: - get_from_env_cached!(ty, key, default, sensitive) - get_bool_from_env_cached!(key, default) Each expands to a block-local `static LazyLock<T>`, so the read + log fire exactly once per call site per process, with no cross-key contention (distinct call sites get distinct statics). Revert lib.rs env logging back to plain info!. Convert the non-lazy hot readers (metastore QW_POSTGRES_*, node_config OTLP/JAEGER, CORS debug) and fold the existing hand-rolled LazyLock env caches (ingest v2 enable/disable, batch bytes, per-index metrics, doc validation, load estimation, field list limit, default load per shard) onto the same macro for consistency. Also drop the rate-limit on the actor-exit success log (back to info!).
Contributor
Author
It's not parsed CLI options, it's reading environment variables, which we logged ~2M times in the last week on the hooray cluster. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
3 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
rate_limited_tracingmacro (rate_limited_infoetc.): the suppressed count is now folded into the emitted line as anum_suppressed=Nfield, instead of a separate preceding line.In combination with #6549, this lets us aggregate on the field and recover the true pre-suppression log count.
3 Types of Log Changes:
INFO→DEBUG(routine per-operation chatter): node pool-add ×4 (the ~907M dominant source), send-to-index-serializer, spawning pipeline, merge schedule/download, leaf split-finished/offsets, offload-to-lambda, resetting pipeline, adding-shards-assignment.INFO→ rate-limitedINFO(1/min) (worth a heartbeat): new-split, actor-exit (success), assigning shards, env-var defaults, truncated-shard.ERROR→ rate-limitedERROR(1/min): the recurring lambda invocation failure (kept visible, not flooding).publish-new-splitsnow carriesnum_splits,num_docs, and total on-disksplit_size.