*: Refine some logging level #6844

JaySon-Huang · 2023-02-18T07:47:49Z

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
- The replica_read_max_thread is useless, especially after this improvement Batch read-index request by start-ts to reduce time cost under high concurrency scenarios #3971
- Simplify the logic of learner read after removing the config

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

Release note

None

ti-chi-bot · 2023-02-18T07:47:52Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

Lloyd-Pottiger
lidezhu

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.

This reverts commit 94d9df2.

JaySon-Huang · 2023-02-20T01:50:21Z

/run-all-tests

JaySon-Huang · 2023-02-20T02:50:05Z

/run-unit-test

JaySon-Huang · 2023-02-20T03:07:45Z

/run-unit-test

Lloyd-Pottiger · 2023-02-20T03:42:01Z

/run-unit-test

flowbehappy · 2023-02-20T04:00:00Z

dbms/src/TiDB/Schema/SchemaSyncService.h

 namespace DB
 {
 class Context;
 class BackgroundProcessingPool;
+class Logger;
+using LoggerPtr = std::shared_ptr<Logger>;


Why use std::shared_ptr instead of Logger*?

After we automatically add filename and lineno to the logging message, the "name" in Poco::Logger is useless. All DB::Logger defaults share the same root Poco::Logger instance and remove the [source=<name>] part from logging.

Sometimes we need a child logger with a specified suffix in the logging, with DB::Logger, it is more convenient, for example, adding a suffix for the reading routine of MPP request with MPPId, or adding a suffix for different tenant id under multi-tenant. #6816 (comment)

If we create Poco::Logger with many different names, the Poco _pLoggerMap will get bigger and bigger without releasing Poco::Logger instances. But DB::Logger always shares the same root Poco::Logger instance.
https://github.com/pingcap/poco/blob/develop/Foundation/src/Logger.cpp#L475-L480

JaySon-Huang · 2023-02-21T05:35:51Z

/merge

ti-chi-bot · 2023-02-21T05:35:53Z

@JaySon-Huang: It seems you want to merge this PR, I will help you trigger all the tests:

/run-all-tests

You only need to trigger /merge once, and if the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.

If you have any questions about the PR merge process, please refer to pr process.

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 ti-community-infra/tichi repository.

ti-chi-bot · 2023-02-21T05:35:54Z

This pull request has been accepted and is ready to merge.

Commit hash: b9cfa00

ti-chi-bot · 2023-02-21T05:36:08Z

@JaySon-Huang: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

trigger some heavy tests which will not run always when PR updated.

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.

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 ti-community-infra/tichi repository.

ti-chi-bot · 2023-02-21T06:27:43Z

In response to a cherrypick label: new pull request created to branch release-6.5: #6866.

Signed-off-by: ti-chi-bot <ti-community-prow-bot@tidb.io>

ti-chi-bot added do-not-merge/needs-linked-issue release-note-none Denotes a PR that doesn't merit a release note. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Feb 18, 2023

JaySon-Huang added 8 commits February 18, 2023 16:17

deprecate aws sdk warnings

2abf3f6

Adjust some log level

7957558

Remove useless code for learner read

f7222ea

Add more info in learner read info logging

fa38998

WALStore read time cost

530f641

Cleanup schema

11bf301

Cleanup Page/Path

cf8c88f

Cleanup misc

6a88e9e

JaySon-Huang force-pushed the adjust_log_level branch from 9c46a74 to 6a88e9e Compare February 18, 2023 08:56

ti-chi-bot added size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. and removed size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Feb 18, 2023

JaySon-Huang added 6 commits February 18, 2023 17:51

Fix blobstore

fdc71f6

Fix sst reader

6ed3296

Align the style for region_id table_id for greping logging

94d9df2

logging level for PageDirectory

04ed0e5

Revert "Align the style for region_id table_id for greping logging"

65047f8

This reverts commit 94d9df2.

Fix compile error

a449a45

ti-chi-bot added size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. and removed size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. labels Feb 18, 2023

Remove useless replicaReadMaxThread

f81a44d

JaySon-Huang requested review from lidezhu and CalvinNeo February 18, 2023 13:52

Add header

e13398e

ti-chi-bot added do-not-merge/needs-triage-completed and removed do-not-merge/needs-linked-issue labels Feb 18, 2023

Format files

cc1cf13

ti-chi-bot added the needs-cherry-pick-release-6.5 Should cherry pick this PR to release-6.5 branch. label Feb 18, 2023

JaySon-Huang mentioned this pull request Feb 18, 2023

*: Refine some logging level (release-6.5) #6846

Closed

12 tasks

Lloyd-Pottiger approved these changes Feb 20, 2023

View reviewed changes

ti-chi-bot added status/LGT1 Indicates that a PR has LGTM 1. needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. labels Feb 20, 2023

JaySon-Huang added 2 commits February 20, 2023 10:43

Merge remote-tracking branch 'upstream/master' into adjust_log_level

f7bcd8a

Fix compile error

a5dd2ed

ti-chi-bot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Feb 20, 2023

flowbehappy reviewed Feb 20, 2023

View reviewed changes

JaySon-Huang and others added 2 commits February 20, 2023 15:58

Fix error

5258e49

Merge branch 'master' into adjust_log_level

b9cfa00

lidezhu approved these changes Feb 20, 2023

View reviewed changes

ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Feb 20, 2023

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Feb 21, 2023

Merge branch 'master' into adjust_log_level

508e1c1

ti-chi-bot merged commit 44de4b5 into pingcap:master Feb 21, 2023

ti-chi-bot mentioned this pull request Feb 21, 2023

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

Closed

12 tasks

ti-chi-bot pushed a commit to ti-chi-bot/tiflash that referenced this pull request Feb 21, 2023

This is an automated cherry-pick of pingcap#6844

33893c1

Signed-off-by: ti-chi-bot <ti-community-prow-bot@tidb.io>

JaySon-Huang deleted the adjust_log_level branch February 21, 2023 07:22

JaySon-Huang mentioned this pull request Dec 21, 2023

*: Refine storage layer logging level (release-6.5) #8558

Merged

12 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: Refine some logging level #6844

*: Refine some logging level #6844

JaySon-Huang commented Feb 18, 2023 •

edited

Loading

ti-chi-bot commented Feb 18, 2023 •

edited

Loading

JaySon-Huang commented Feb 20, 2023

JaySon-Huang commented Feb 20, 2023

JaySon-Huang commented Feb 20, 2023

Lloyd-Pottiger commented Feb 20, 2023

flowbehappy Feb 20, 2023

JaySon-Huang Feb 20, 2023 •

edited

Loading

JaySon-Huang commented Feb 21, 2023

ti-chi-bot commented Feb 21, 2023

ti-chi-bot commented Feb 21, 2023

ti-chi-bot commented Feb 21, 2023

ti-chi-bot commented Feb 21, 2023

*: Refine some logging level #6844

*: Refine some logging level #6844

Conversation

JaySon-Huang commented Feb 18, 2023 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

ti-chi-bot commented Feb 18, 2023 • edited Loading

JaySon-Huang commented Feb 20, 2023

JaySon-Huang commented Feb 20, 2023

JaySon-Huang commented Feb 20, 2023

Lloyd-Pottiger commented Feb 20, 2023

flowbehappy Feb 20, 2023

Choose a reason for hiding this comment

JaySon-Huang Feb 20, 2023 • edited Loading

Choose a reason for hiding this comment

JaySon-Huang commented Feb 21, 2023

ti-chi-bot commented Feb 21, 2023

ti-chi-bot commented Feb 21, 2023

ti-chi-bot commented Feb 21, 2023

ti-chi-bot commented Feb 21, 2023

JaySon-Huang commented Feb 18, 2023 •

edited

Loading

ti-chi-bot commented Feb 18, 2023 •

edited

Loading

JaySon-Huang Feb 20, 2023 •

edited

Loading