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

JaySon-Huang · 2023-12-21T04:56:01Z

Cherry-pick to release-6.5

What problem does this PR solve?

Issue Number: ref #8563

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 second or unavailable regions exist, use info level, else debug level
- For PS v3 GC, if full GC or WAL compact happen use info level, else debug level
- For physically drop tables, log down the tombstone timestamp
- For exceptions thrown in FFI functions
Use dag_request->ShortDebugString to reduce some useless spaces
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

ref pingcap#8365

JaySon-Huang · 2023-12-22T08:08:01Z

/run-all-tests

JaySon-Huang · 2023-12-22T11:03:08Z

/run-all-tests

…evel_650

JaySon-Huang · 2023-12-25T03:18:45Z

/run-all-tests

Lloyd-Pottiger

LGTM~

dbms/src/Storages/Transaction/TiDB.cpp

Co-authored-by: Lloyd-Pottiger <60744015+Lloyd-Pottiger@users.noreply.github.com>

JaySon-Huang · 2023-12-25T04:01:33Z

/run-all-tests

JinheLin · 2023-12-25T04:23:27Z

I suggest changing these logs to INFO as well: JaySon-Huang#26

ti-chi-bot · 2023-12-25T05:16:58Z

[LGTM Timeline notifier]

Timeline:

2023-12-25 03:51:22.675131697 +0000 UTC m=+1451373.712358628: ☑️ agreed by Lloyd-Pottiger.
2023-12-25 05:16:57.222334258 +0000 UTC m=+1456508.259561184: ☑️ agreed by JinheLin.

JaySon-Huang · 2023-12-25T05:43:00Z

/run-all-tests

JaySon-Huang · 2023-12-25T06:01:01Z

/run-all-tests

CalvinNeo

lgtm

ti-chi-bot · 2023-12-25T06:34:31Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: CalvinNeo, JinheLin, Lloyd-Pottiger

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~~ [CalvinNeo,JinheLin,Lloyd-Pottiger]

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

Adjust some log level

01e4973

JaySon-Huang changed the title ~~[WIP] *: Refine some logging level (release-6.5)~~ [WIP] *: Refine storage layer logging level (release-6.5) Dec 21, 2023

Resolve conflict

5c5b7a1

JaySon-Huang mentioned this pull request Dec 21, 2023

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

Closed

12 tasks

JaySon-Huang added 3 commits December 21, 2023 16:18

Refine learner read

7482aca

Refine physical drop tables

499705d

Fix some logging

c69423d

JaySon-Huang force-pushed the adjust_log_level_650 branch from 82116fb to c69423d Compare December 21, 2023 08:18

CalvinNeo and others added 3 commits December 21, 2023 16:30

Set log level to FATAL on FFI boundary on exception (pingcap#8364)

2d2271c

ref pingcap#8365

Align some level when query

7486700

Fix log lvl in schema sync

b6219d0

JaySon-Huang changed the title ~~[WIP] *: Refine storage layer logging level (release-6.5)~~ *: Refine storage layer logging level (release-6.5) Dec 22, 2023

ti-chi-bot bot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Dec 22, 2023

JaySon-Huang added 3 commits December 22, 2023 18:27

Add mvcc details output in MPPTaskStatistics

3994c6e

Fix ut compile error

4644974

Clean some changes

1d555b7

JaySon-Huang force-pushed the adjust_log_level_650 branch from 0a8bcd3 to 1d555b7 Compare December 22, 2023 10:29

JaySon-Huang added 3 commits December 25, 2023 11:05

Fix include

1b4471a

Merge remote-tracking branch 'upstream/release-6.5' into adjust_log_l…

09aad65

…evel_650

Fix include

c46b7bd

JaySon-Huang requested review from CalvinNeo, JinheLin and Lloyd-Pottiger December 25, 2023 03:29

Lloyd-Pottiger approved these changes Dec 25, 2023

View reviewed changes

dbms/src/Storages/Transaction/TiDB.cpp Outdated Show resolved Hide resolved

ti-chi-bot bot added needs-1-more-lgtm Indicates a PR needs 1 more LGTM. approved labels Dec 25, 2023

Update dbms/src/Storages/Transaction/TiDB.cpp

36f656f

Co-authored-by: Lloyd-Pottiger <60744015+Lloyd-Pottiger@users.noreply.github.com>

add log about read thread (#26)

822345e

JinheLin approved these changes Dec 25, 2023

View reviewed changes

ti-chi-bot bot added lgtm and removed needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Dec 25, 2023

ti-chi-bot added the cherry-pick-approved Cherry pick PR approved by release team. label Dec 25, 2023

ti-chi-bot bot removed the do-not-merge/cherry-pick-not-approved label Dec 25, 2023

Fix time unit

3ca9c2d

CalvinNeo approved these changes Dec 25, 2023

View reviewed changes

ti-chi-bot bot merged commit a24ca73 into pingcap:release-6.5 Dec 25, 2023

JaySon-Huang deleted the adjust_log_level_650 branch December 25, 2023 07:34

ti-chi-bot removed the cherry-pick-approved Cherry pick PR approved by release team. label Dec 27, 2023

ti-chi-bot bot added the do-not-merge/cherry-pick-not-approved label Dec 27, 2023

ti-chi-bot added the cherry-pick-approved Cherry pick PR approved by release team. label Dec 27, 2023

ti-chi-bot bot removed the do-not-merge/cherry-pick-not-approved label Dec 27, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

JaySon-Huang commented Dec 21, 2023 •

edited

Loading

JaySon-Huang commented Dec 22, 2023

JaySon-Huang commented Dec 22, 2023

JaySon-Huang commented Dec 25, 2023

Lloyd-Pottiger left a comment

JaySon-Huang commented Dec 25, 2023

JinheLin commented Dec 25, 2023

ti-chi-bot bot commented Dec 25, 2023

JaySon-Huang commented Dec 25, 2023

JaySon-Huang commented Dec 25, 2023

CalvinNeo left a comment

ti-chi-bot bot commented Dec 25, 2023

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

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

Conversation

JaySon-Huang commented Dec 21, 2023 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

JaySon-Huang commented Dec 22, 2023

JaySon-Huang commented Dec 22, 2023

JaySon-Huang commented Dec 25, 2023

Lloyd-Pottiger left a comment

Choose a reason for hiding this comment

JaySon-Huang commented Dec 25, 2023

JinheLin commented Dec 25, 2023

ti-chi-bot bot commented Dec 25, 2023

[LGTM Timeline notifier]

JaySon-Huang commented Dec 25, 2023

JaySon-Huang commented Dec 25, 2023

CalvinNeo left a comment

Choose a reason for hiding this comment

ti-chi-bot bot commented Dec 25, 2023

JaySon-Huang commented Dec 21, 2023 •

edited

Loading