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

*: Refine some logging level (#6844) #6866

Conversation

ti-chi-bot
Copy link
Member

This is an automated cherry-pick of #6844

What problem does this PR solve?

Issue Number: ref #6845

Problem Summary:

With logging level "info",

Before this PR when there is no write && read on tiflash, there are more than 15 logging every 30 seconds
[2023/02/18 16:41:31.702 +08:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=47]
[2023/02/18 16:41:36.725 +08:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=47]
[2023/02/18 16:41:41.744 +08:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=47]
[2023/02/18 16:41:46.768 +08:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=47]
[2023/02/18 16:41:51.788 +08:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=47]
[2023/02/18 16:41:52.105 +08:00] [DEBUG] [GCManager.cpp:46] ["Start GC with table id: 4"] [source=GCManager] [thread_id=51]
[2023/02/18 16:41:52.106 +08:00] [DEBUG] [GCManager.cpp:101] ["End GC and next gc will start with table id: 4"] [source=GCManager] [thread_id=51]
[2023/02/18 16:41:56.808 +08:00] [INFO] [RateLimiter.cpp:715] ["limiter 0 write 0 read 0 NOT need to tune."] [source=IOLimitTuner] [thread_id=47]
[2023/02/18 16:42:01.579 +08:00] [INFO] [BlobStore.cpp:1078] ["BlobStore gc get status done. gc info: Read-Only Blob: [null]. No GC Blob: [null]. Full GC Blob: [null]. Truncated Blob: [null]."] [source=__global__.meta] [thread_id=55]
[2023/02/18 16:42:01.579 +08:00] [INFO] [GCDefines.cpp:127] ["GC finished without full gc. [total time=0ms] [compact wal=0ms] [compact directory=0ms] [compact spacemap=0ms] [gc status=0ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=__global__.meta] [thread_id=55]
[2023/02/18 16:42:01.579 +08:00] [INFO] [BlobStore.cpp:1078] ["BlobStore gc get status done. gc info: Read-Only Blob: [null]. No GC Blob: [null]. Full GC Blob: [null]. Truncated Blob: [null]."] [source=__global__.data] [thread_id=55]
[2023/02/18 16:42:01.579 +08:00] [INFO] [GCDefines.cpp:127] ["GC finished without full gc. [total time=0ms] [compact wal=0ms] [compact directory=0ms] [compact spacemap=0ms] [gc status=0ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=__global__.data] [thread_id=55]
[2023/02/18 16:42:01.579 +08:00] [INFO] [BlobStore.cpp:1078] ["BlobStore gc get status done. gc info: Read-Only Blob: [null]. No GC Blob: [null]. Full GC Blob: [null]. Truncated Blob: [null]."] [source=__global__.log] [thread_id=55]
[2023/02/18 16:42:01.579 +08:00] [INFO] [GCDefines.cpp:127] ["GC finished without full gc. [total time=0ms] [compact wal=0ms] [compact directory=0ms] [compact spacemap=0ms] [gc status=0ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=__global__.log] [thread_id=55]
After this PR, when there is no write && read, there is only 2 logging every 10 minutes
[2023/02/18 19:50:44.662 +08:00] [INFO] [PageDirectory.cpp:1432] ["GC apply done. [edit size=6]"] [source=__global__.meta] [thread_id=15]
[2023/02/18 19:50:44.662 +08:00] [INFO] [GCDefines.cpp:145] ["GC finished. [total time=0ms] [compact wal=0ms] [compact directory=0ms] [compact spacemap=0ms] [gc status=0ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=__global__.meta] [thread_id=15]
[2023/02/18 19:50:44.663 +08:00] [INFO] [DeltaMergeStore_InternalBg.cpp:164] ["GC removed useless DM file, dmfile=/data1/jaysonhuang/tiupd/data/tiflash-5010/data/t_84/stable/.del.dmf_17"] [source="table_id=84"] [thread_id=15]
[2023/02/18 19:50:44.665 +08:00] [INFO] [DeltaMergeStore_InternalBg.cpp:164] ["GC removed useless DM file, dmfile=/data1/jaysonhuang/tiupd/data/tiflash-5010/data/t_84/stable/.del.dmf_18"] [source="table_id=84"] [thread_id=15]
[2023/02/18 19:50:44.666 +08:00] [INFO] [DeltaMergeStore_InternalBg.cpp:164] ["GC removed useless DM file, dmfile=/data1/jaysonhuang/tiupd/data/tiflash-5010/data/t_84/stable/.del.dmf_24"] [source="table_id=84"] [thread_id=15]
[2023/02/18 19:51:49.747 +08:00] [INFO] [BlobStore.cpp:545] ["Removing BlobFile [blob_id=4]"] [source=__global__.meta] [thread_id=16]
[2023/02/18 19:52:19.859 +08:00] [INFO] [SchemaSyncService.cpp:100] ["Performing GC using safe point 439542201895354368"] [thread_id=17]
[2023/02/18 19:52:19.859 +08:00] [INFO] [SchemaSyncService.cpp:216] ["Performed GC using safe point 439542201895354368"] [thread_id=17]
[2023/02/18 20:02:19.764 +08:00] [INFO] [SchemaSyncService.cpp:100] ["Performing GC using safe point 439542359181754368"] [thread_id=20]
[2023/02/18 20:02:19.765 +08:00] [INFO] [SchemaSyncService.cpp:216] ["Performed GC using safe point 439542359181754368"] [thread_id=20]
[2023/02/18 20:12:19.811 +08:00] [INFO] [SchemaSyncService.cpp:100] ["Performing GC using safe point 439542516468154368"] [thread_id=22]
[2023/02/18 20:12:19.811 +08:00] [INFO] [SchemaSyncService.cpp:216] ["Performed GC using safe point 439542516468154368"] [thread_id=22]
[2023/02/18 20:22:21.692 +08:00] [INFO] [SchemaSyncService.cpp:100] ["Performing GC using safe point 439542673754554368"] [thread_id=21]
[2023/02/18 20:22:21.692 +08:00] [INFO] [SchemaSyncService.cpp:216] ["Performed GC using safe point 439542673754554368"] [thread_id=21]
[2023/02/18 20:32:21.847 +08:00] [INFO] [SchemaSyncService.cpp:100] ["Performing GC using safe point 439542831041216512"] [thread_id=19]
[2023/02/18 20:32:21.847 +08:00] [INFO] [SchemaSyncService.cpp:216] ["Performed GC using safe point 439542831041216512"] [thread_id=19]
[2023/02/18 20:42:22.364 +08:00] [INFO] [SchemaSyncService.cpp:100] ["Performing GC using safe point 439542988353568768"] [thread_id=16]
[2023/02/18 20:42:22.365 +08:00] [INFO] [SchemaSyncService.cpp:216] ["Performed GC using safe point 439542988353568768"] [thread_id=16]
[2023/02/18 20:53:18.848 +08:00] [INFO] [SchemaSyncService.cpp:100] ["Performing GC using safe point 439543161355763712"] [thread_id=25]
[2023/02/18 20:53:18.849 +08:00] [INFO] [SchemaSyncService.cpp:216] ["Performed GC using safe point 439543161355763712"] [thread_id=25]

What is changed and how it works?

  • Refine some logging level
    • For learner read, if time elapsed is longer than 1 seconds, use info level, else debug level
    • IOLimitTuner use debug level when there is nothing need to tune
    • For PS v3 GC, if full GC or WAL compact happen use info level, else debug level
  • Replace Poco::Logger with DB::Logger
  • Remove flash.replica_read_max_thread

Check List

Tests

  • Unit test
  • Integration test
  • Manual test (add detailed scripts or steps below)
  • No code

Side effects

  • Performance regression: Consumes more CPU
  • Performance regression: Consumes more Memory
  • Breaking backward compatibility

Documentation

  • Affects user behaviors
  • Contains syntax changes
  • Contains variable changes
  • Contains experimental features
  • Changes MySQL compatibility

Release note

None

@ti-chi-bot
Copy link
Member Author

[REVIEW NOTIFICATION]

This pull request has not been approved.

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

The full list of commands accepted by this bot can be found here.

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

@ti-chi-bot ti-chi-bot added release-note-none Denotes a PR that doesn't merit a release note. do-not-merge/cherry-pick-not-approved size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. type/cherry-pick-for-release-6.5 This PR is cherry-picked to release-6.5 from a source PR. labels Feb 21, 2023
@ti-chi-bot ti-chi-bot mentioned this pull request Feb 21, 2023
12 tasks
@ti-chi-bot
Copy link
Member Author

@ti-chi-bot: This cherry pick PR is for a release branch and has not yet been approved by release team.
Adding the do-not-merge/cherry-pick-not-approved label.

To merge this cherry pick, it must first be approved by the collaborators.

AFTER it has been approved by collaborators, please ping the release team in a comment to request a cherry pick review.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

@JaySon-Huang
Copy link
Contributor

duplicated with #6846

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
do-not-merge/cherry-pick-not-approved release-note-none Denotes a PR that doesn't merit a release note. size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. type/cherry-pick-for-release-6.5 This PR is cherry-picked to release-6.5 from a source PR.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants