Log Surge

Translated
1

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

Original topic: 日志暴增

| username: 等一分钟

[2022/10/12 10:26:38.179 +08:00] [WARN] [collate.go:145] [“Unable to get collator by name, use binCollator instead.”] [name=] [stack=“github.com/pingcap/tidb/util/collate.GetCollator
\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tidb/util/collate/collate.go:148
github.com/pingcap/tidb/types.CompareString
\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tidb/types/compare.go:118
github.com/pingcap/tidb/types.(*Datum).compareBinaryLiteral
\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tidb/types/datum.go:772
github.com/pingcap/tidb/types.(*Datum).CompareDatum
\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tidb/types/datum.go:592
github.com/pingcap/tidb/statistics.(*sampleItemSorter).Less
\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tidb/statistics/sample.go:80
sort.insertionSort
\t/usr/local/go/src/sort/sort.go:40
sort.stable
\t/usr/local/go/src/sort/sort.go:385
sort.Stable
\t/usr/local/go/src/sort/sort.go:378
github.com/pingcap/tidb/statistics.SortSampleItems
\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tidb/statistics/sample.go:64
github.com/pingcap/tidb/statistics.BuildHistAndTopN
\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tidb/statistics/builder.go:244
github.com/pingcap/tidb/executor.(*AnalyzeColumnsExec).subBuildWorker
\t/home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tidb/executor/analyze.go:1330”]

2
| username: Billmay表妹 | Original post link

When describing the problem, please follow:
【TiDB Usage Environment】Production Environment / Testing / PoC
【TiDB Version】
【Encountered Problem】
【Reproduction Path】What operations were performed that led to the problem
【Problem Phenomenon and Impact】

Describe as much effective background information as possible. Many problems may have different suggestions under different scenarios and business contexts. If you don’t explain clearly, it will make it difficult for everyone to help~

3
| username: 等一分钟 | Original post link

These types of logs are increasing rapidly, and the disk will be full soon.

4
| username: 等一分钟 | Original post link

[2022/10/12 10:35:17.966 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:3.471352099s txnStartTS:436611868457959470 region_id:81356146 store_addr:10.0.254.151:20160 kv_process_ms:2683 kv_wait_ms:781 kv_read_ms:180 processed_versions:9686 total_versions:11253 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:16251 rocksdb_cache_hit_count:39255 rocksdb_read_count:1 rocksdb_read_byte:16327”] [conn=60427]
[2022/10/12 10:35:17.975 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:307.0573ms txnStartTS:436611868366209053 region_id:82321774 store_addr:10.0.254.152:20160 kv_process_ms:277 kv_wait_ms:23 kv_read_ms:242 processed_versions:4023 total_versions:4083 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:182 rocksdb_cache_hit_count:52558 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=60411]
[2022/10/12 10:35:17.975 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:1.671915062s txnStartTS:436611868379316297 region_id:82338077 store_addr:10.0.254.151:20160 kv_process_ms:1383 kv_wait_ms:282 kv_read_ms:186 processed_versions:3933 total_versions:3993 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:184 rocksdb_cache_hit_count:51355 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=60417]
[2022/10/12 10:35:18.000 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_WAIT] resp_time:594.041432ms txnStartTS:436611869296820255 region_id:79305440 store_addr:10.0.254.153:20160 kv_process_ms:0 kv_wait_ms:592 kv_read_ms:0 processed_versions:0 total_versions:0 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:0 rocksdb_cache_hit_count:0 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=60449]
[2022/10/12 10:35:18.006 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_WAIT] resp_time:600.535469ms txnStartTS:436611869296820255 region_id:78561746 store_addr:10.0.254.153:20160 kv_process_ms:0 kv_wait_ms:598 kv_read_ms:0 processed_versions:3 total_versions:3 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:0 rocksdb_cache_hit_count:40 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=60449]
[2022/10/12 10:35:18.009 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:767.531185ms txnStartTS:436611868929818639 region_id:78671164 store_addr:10.0.254.151:20160 kv_process_ms:212 kv_wait_ms:548 kv_read_ms:3 processed_versions:60 total_versions:67 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:23 rocksdb_cache_hit_count:640 rocksdb_read_count:1 rocksdb_read_byte:2148”] [conn=60433]
[2022/10/12 10:35:18.013 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:771.680852ms txnStartTS:436611868929818639 region_id:81840147 store_addr:10.0.254.151:20160 kv_process_ms:221 kv_wait_ms:549 kv_read_ms:4 processed_versions:156 total_versions:175 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:189 rocksdb_cache_hit_count:960 rocksdb_read_count:1 rocksdb_read_byte:5668”] [conn=60433]
[2022/10/12 10:35:18.013 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:1.247759311s txnStartTS:436611869296820255 region_id:81840147 store_addr:10.0.254.151:20160 kv_process_ms:872 kv_wait_ms:365 kv_read_ms:272 processed_versions:6368 total_versions:6888 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:2410 rocksdb_cache_hit_count:64844 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=60449]
[2022/10/12 10:35:18.032 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:711.852499ms txnStartTS:436611868929818639 region_id:78671164 store_addr:10.0.254.151:20160 kv_process_ms:204 kv_wait_ms:508 kv_read_ms:3 processed_versions:60 total_versions:69 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:27 rocksdb_cache_hit_count:651 rocksdb_read_count:1 rocksdb_read_byte:3173”] [conn=60433]
[2022/10/12 10:35:18.077 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:676.589179ms txnStartTS:436611868929818639 region_id:78671164 store_addr:10.0.254.151:20160 kv_process_ms:216 kv_wait_ms:460 kv_read_ms:9 processed_versions:151 total_versions:182 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:183 rocksdb_cache_hit_count:1112 rocksdb_read_count:2 rocksdb_read_byte:9799”] [conn=60433]
[2022/10/12 10:35:18.083 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:683.167256ms txnStartTS:436611868929818639 region_id:81840147 store_addr:10.0.254.151:20160 kv_process_ms:218 kv_wait_ms:464 kv_read_ms:7 processed_versions:196 total_versions:221 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:207 rocksdb_cache_hit_count:1395 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=60433]

5
| username: 等一分钟 | Original post link

Version: v5.2.3

6
| username: buddyyuan | Original post link

Refer to this

7
| username: 等一分钟 | Original post link

[2022/10/12 10:50:09.890 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:362.506862ms txnStartTS:436612104702132247 region_id:82311112 store_addr:10.0.5.60:20160 kv_process_ms:312 kv_wait_ms:42 kv_read_ms:125 processed_versions:3878 total_versions:3939 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:187 rocksdb_cache_hit_count:46596 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=61885]
[2022/10/12 10:50:09.890 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:1.804818709s txnStartTS:436612104675917856 region_id:81928694 store_addr:10.0.254.153:20160 kv_process_ms:1515 kv_wait_ms:285 kv_read_ms:160 processed_versions:3861 total_versions:3918 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:171 rocksdb_cache_hit_count:50411 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=61875]
[2022/10/12 10:50:09.897 +08:00] [INFO] [coprocessor.go:812] [“[TIME_COP_PROCESS] resp_time:1.371839489s txnStartTS:436612104702132241 region_id:82126616 store_addr:10.0.254.151:20160 kv_process_ms:1115 kv_wait_ms:247 kv_read_ms:116 processed_versions:2378 total_versions:2906 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:1700 rocksdb_cache_hit_count:25911 rocksdb_read_count:0 rocksdb_read_byte:0”] [conn=61883]

8
| username: 等一分钟 | Original post link

A lot of information.

9
| username: 等一分钟 | Original post link

Can the cause be determined from the logs?

10
| username: 等一分钟 | Original post link

Indeed, there is an analyze operation. Is there a bug in this version?

11
| username: 等一分钟 | Original post link

Restarting the tidb_server node didn’t work either.

12
| username: TiDBer_CEVsub | Original post link

Turn off the logs, or investigate the issues in the business system.

13
| username: wuxiangdong | Original post link

Adjust the log level.

14
| username: zhouzeru | Original post link

Modify the logging strategy and then troubleshoot other issues.

15
| username: 张雨齐0720 | Original post link

From this, it has always been at the warn log level. To avoid the disk getting full, first change it to error to avoid printing logs, and then investigate further.
I see someone has already posted a solution. You can give it a try.

16
| username: 等一分钟 | Original post link

It seems the situation is different. I update the statistics every day at midnight, and I restarted the tidb_server at noon. Now there are new statistics updates again.

17
| username: 等一分钟 | Original post link

I heard that there is a command that can refresh the configuration set by ‘set global’ back to the configuration file. I don’t know which command it is.

18
| username: wisdom | Original post link

What log level

19
| username: 近墨者zyl | Original post link

Case study, thank you.

20
| username: system | Original post link

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.