Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(cli): log cache full when on debug level #3085

Merged
merged 9 commits into from Aug 3, 2023

Conversation

arouene
Copy link
Contributor

@arouene arouene commented Jun 19, 2023

Simple debug log addition to help diagnose of duplicate downloading of blobs.
fixes #3059

@arouene arouene changed the title Log full cache when on debug level fix(cli): Log cache full when on debug level Jun 19, 2023
@arouene arouene changed the title fix(cli): Log cache full when on debug level fix(cli): log cache full when on debug level Jun 19, 2023
@arouene
Copy link
Contributor Author

arouene commented Jun 22, 2023

I was wondering, how about to set it to warning level instead of debug level ? As a Kopia user, I would like to know if the cache is full, leading to an increase cost of bandwidth, and an increased time to achieve the maintenance.

@codecov
Copy link

codecov bot commented Jul 4, 2023

Codecov Report

Patch coverage: 14.28% and project coverage change: +0.03% 🎉

Comparison is base (14e6ee7) 75.37% compared to head (94b35e7) 75.40%.
Report is 6 commits behind head on master.

Additional details and impacted files
@@            Coverage Diff             @@
##           master    #3085      +/-   ##
==========================================
+ Coverage   75.37%   75.40%   +0.03%     
==========================================
  Files         459      459              
  Lines       36408    36451      +43     
==========================================
+ Hits        27442    27486      +44     
- Misses       7044     7047       +3     
+ Partials     1922     1918       -4     
Files Changed Coverage Δ
internal/cache/persistent_lru_cache.go 91.56% <14.28%> (-1.38%) ⬇️

... and 10 files with indirect coverage changes

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@arouene arouene requested a review from jkowalski July 5, 2023 19:26
@julio-lopez
Copy link
Collaborator

@arouene Please address the linter issues. Thanks.

@arouene
Copy link
Contributor Author

arouene commented Aug 2, 2023

@arouene Please address the linter issues. Thanks.

Done, thanks !

@julio-lopez julio-lopez enabled auto-merge (squash) August 3, 2023 05:36
if clock.Now().Sub(c.lastCacheWarning) > time.Minute {
c.lastCacheWarning = clock.Now()

log(ctx).Warnf("Cache is full, unable to add %v into cache.", key)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should make this Debug down the road.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This can be pretty noisy, even once per minute. Some workflows take several hours.

If the cache is full, are not we making the situation worse by filling up the logs ??

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Shrekster yes, we should

  • reduce the frequency
  • add counters

Copy link
Collaborator

@Shrekster Shrekster Aug 3, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I discussed this partly offline. I think the write rate could be reduced, but even better I'd propose we just log once and then mute.

If we can settle on logging this once then this doesn't even need to be a debug log and that could be more useful upfront than having to turn on debug logs on a second run.

The alternate question to "how much logging is bad logging?" is maybe "what frequency is useful ?"

IMO once is ok for this becuase logging this the second time is only telling me that nothing got expired, but what debugging info do I get from it ? If cache was full once and the perf was crappy then that probably explains it.

Is the second log going to add more info ? Yes!

Does that more info help ? I don't know... doesn't seem like yet

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Shrekster PTAL at #3193

@julio-lopez julio-lopez merged commit e98eb37 into kopia:master Aug 3, 2023
26 of 27 checks passed
julio-lopez added a commit to kastenhq/kopia that referenced this pull request Aug 3, 2023
…nutes

Addresses concernes about too many messages in the logs (kopia#3085)
julio-lopez added a commit to kastenhq/kopia that referenced this pull request Aug 3, 2023
Instead log the cache description, which provides information about
the types of contents being cached.

Followup to kopia#3085
:
julio-lopez added a commit that referenced this pull request Aug 3, 2023
fix(general): change cache full logging frequency to once every 10 minutes
Addresses concerns about too many messages in the logs (#3085)

fix(general): avoid logging cache key.
Instead log the cache description, which provides information about
the types of contents being cached.

Followups to #3085
@arouene arouene deleted the log-cache-full branch August 3, 2023 22:22
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Maintenance job getting ~2000 times the same file, with huge performance and cost impact
4 participants