TiDB的analyze table执行时间段，时区问题。

zhimadi · 2021 年2 月 22 日 06:02

为提高效率，请提供以下信息，问题描述清晰能够更快得到解决：

【TiDB 版本】
v4.0.9
【问题描述】
原本的设置：

mysql> show global variables like 'tidb%ana%';
+------------------------------+-------------+
| Variable_name                | Value       |
+------------------------------+-------------+
| tidb_auto_analyze_end_time   | 23:59 +0000 |
| tidb_auto_analyze_ratio      | 0.5         |
| tidb_auto_analyze_start_time | 00:00 +0000 |
| tidb_enable_fast_analyze     | 0           |
+------------------------------+-------------+
4 rows in set

我首先使用以下命令并成功设置：

set global tidb_auto_analyze_ratio=0.2;
set global tidb_auto_analyze_start_time='01:00 +0800';
set global tidb_auto_analyze_end_time='05:00 +0800';

然后我编辑edit-config，删除了server_configs.tidb的performance.run-auto-analyze: false，
再使用tiup cluster reload xxx-cluster -R tidb。

验证:

mysql> select @@tidb_auto_analyze_start_time;
+--------------------------------+
| @@tidb_auto_analyze_start_time |
+--------------------------------+
| 01:00 +0800                    |
+--------------------------------+
1 row in set (0.00 sec)

mysql> select @@tidb_auto_analyze_end_time;
+------------------------------+
| @@tidb_auto_analyze_end_time |
+------------------------------+
| 05:00 +0800                  |
+------------------------------+
1 row in set (0.01 sec)

最后结果是analyze执行的时间跟设置的不相符。请问这个是什么原因？

若提问为性能优化、故障排查类问题，请下载脚本运行。终端输出的打印结果，请务必全选并复制粘贴上传。

来了老弟 · 2021 年2 月 22 日 06:07

你好，请上传下 tidb.log 我看下其中是否有 auto analyze table 的信息。

zhimadi · 2021 年2 月 22 日 06:16

你好，有三台机器。
tidb-00:

tidb-01:

[2021/02/22 13:48:34.977 +08:00] [INFO] [manager.go:301] ["revoke session"] ["owner info"="[bindinfo] /tidb/bindinfo/owner ownerManager fe58f8d8-b83d-47e0-a2f3-072bc237e10c"] [error="rpc error: code = Canceled desc = grpc: the client connection is closing"]
[2021/02/22 13:48:34.977 +08:00] [INFO] [domain.go:950] ["handleEvolvePlanTasksLoop exited."]
[2021/02/22 13:48:34.995 +08:00] [INFO] [manager.go:301] ["revoke session"] ["owner info"="[stats] /tidb/stats/owner ownerManager fe58f8d8-b83d-47e0-a2f3-072bc237e10c"] [error="rpc error: code = Canceled desc = grpc: the client connection is closing"]
[2021/02/22 13:48:34.995 +08:00] [INFO] [domain.go:622] ["domain closed"] ["take time"=1.244418581s]
[2021/02/22 13:48:35.029 +08:00] [INFO] [printer.go:33] ["Welcome to TiDB."] ["Release Version"=v4.0.9] [Edition=Community] ["Git Commit Hash"=69f05ea55e8409152a7721b2dd8822af011355ea] ["Git Branch"=heads/refs/tags/v4.0.9] ["UTC Build Time"="2020-12-21 04:26:49"] [GoVersion=go1.13] ["Race Enabled"=false] ["Check Table Before Drop"=false] ["TiKV Min Version"=v3.0.0-60965b006877ca7234adaced7890d7b029ed1306]
[2021/02/22 13:48:35.030 +08:00] [INFO] [printer.go:47] ["loaded config"] [config="{\"host\":\"0.0.0.0\",\"advertise-address\":\"172.18.163.109\",\"port\":4000,\"cors\":\"\",\"store\":\"tikv\",\"path\":\"172.18.163.110:2379,172.18.163.109:2379,172.18.163.107:2379\",\"socket\":\"\",\"lease\":\"45s\",\"run-ddl\":true,\"split-table\":false,\"token-limit\":1000,\"oom-use-tmp-storage\":true,\"tmp-storage-path\":\"/tmp/1001_tidb/MC4wLjAuMDo0MDAwLzAuMC4wLjA6MTAwODA=/tmp-storage\",\"oom-action\":\"log\",\"mem-quota-query\":1073741824,\"tmp-storage-quota\":-1,\"enable-streaming\":false,\"enable-batch-dml\":false,\"lower-case-table-names\":2,\"server-version\":\"\",\"log\":{\"level\":\"info\",\"format\":\"text\",\"disable-timestamp\":null,\"enable-timestamp\":null,\"disable-error-stack\":null,\"enable-error-stack\":null,\"file\":{\"filename\":\"/tidb/deploy/tidb-4000/log/tidb.log\",\"max-size\":300,\"max-days\":0,\"max-backups\":0},\"enable-slow-log\":true,\"slow-query-file\":\"log/tidb_slow_query.log\",\"slow-threshold\":300,\"expensive-threshold\":10000,\"query-log-max-len\":4096,\"record-plan-in-slow-log\":1},\"security\":{\"skip-grant-table\":false,\"ssl-ca\":\"\",\"ssl-cert\":\"\",\"ssl-key\":\"\",\"require-secure-transport\":false,\"cluster-ssl-ca\":\"\",\"cluster-ssl-cert\":\"\",\"cluster-ssl-key\":\"\",\"cluster-verify-cn\":null},\"status\":{\"status-host\":\"0.0.0.0\",\"metrics-addr\":\"\",\"status-port\":10080,\"metrics-interval\":15,\"report-status\":true,\"record-db-qps\":false},\"performance\":{\"max-procs\":0,\"max-memory\":0,\"server-memory-quota\":0,\"memory-usage-alarm-ratio\":0.8,\"stats-lease\":\"3s\",\"stmt-count-limit\":5000,\"feedback-probability\":0,\"query-feedback-limit\":512,\"pseudo-estimate-ratio\":0.8,\"force-priority\":\"NO_PRIORITY\",\"bind-info-lease\":\"3s\",\"txn-total-size-limit\":104857600,\"tcp-keep-alive\":true,\"cross-join\":true,\"run-auto-analyze\":true,\"agg-push-down-join\":false,\"committer-concurrency\":16,\"max-txn-ttl\":600000,\"gogc\":100},\"prepared-plan-cache\":{\"enabled\":false,\"capacity\":100,\"memory-guard-ratio\":0.1},\"opentracing\":{\"enable\":false,\"rpc-metrics\":false,\"sampler\":{\"type\":\"const\",\"param\":1,\"sampling-server-url\":\"\",\"max-operations\":0,\"sampling-refresh-interval\":0},\"reporter\":{\"queue-size\":0,\"buffer-flush-interval\":0,\"log-spans\":false,\"local-agent-host-port\":\"\"}},\"proxy-protocol\":{\"networks\":\"\",\"header-timeout\":5},\"tikv-client\":{\"grpc-connection-count\":4,\"grpc-keepalive-time\":10,\"grpc-keepalive-timeout\":3,\"commit-timeout\":\"41s\",\"max-batch-size\":128,\"overload-threshold\":200,\"max-batch-wait-time\":0,\"batch-wait-size\":8,\"enable-chunk-rpc\":true,\"region-cache-ttl\":600,\"store-limit\":0,\"store-liveness-timeout\":\"5s\",\"copr-cache\":{\"enable\":true,\"capacity-mb\":1000,\"admission-max-ranges\":500,\"admission-max-result-mb\":10,\"admission-min-process-ms\":5}},\"binlog\":{\"enable\":false,\"ignore-error\":false,\"write-timeout\":\"15s\",\"binlog-socket\":\"\",\"strategy\":\"range\"},\"compatible-kill-query\":false,\"plugin\":{\"dir\":\"\",\"load\":\"\"},\"pessimistic-txn\":{\"enable\":true,\"max-retry-count\":256},\"check-mb4-value-in-utf8\":true,\"max-index-length\":3072,\"graceful-wait-before-shutdown\":0,\"alter-primary-key\":false,\"treat-old-version-utf8-as-utf8mb4\":true,\"enable-table-lock\":false,\"delay-clean-table-lock\":0,\"split-region-max-num\":1000,\"stmt-summary\":{\"enable\":true,\"enable-internal-query\":false,\"max-stmt-count\":200,\"max-sql-length\":4096,\"refresh-interval\":1800,\"history-size\":24},\"repair-mode\":false,\"repair-table-list\":[],\"isolation-read\":{\"engines\":[\"tikv\",\"tiflash\",\"tidb\"]},\"max-server-connections\":0,\"new_collations_enabled_on_first_bootstrap\":false,\"experimental\":{\"allow-expression-index\":false},\"enable-collect-execution-info\":true,\"skip-register-to-dashboard\":false,\"enable-telemetry\":true}"]
[2021/02/22 13:48:35.030 +08:00] [INFO] [main.go:304] ["disable Prometheus push client"]

tidb-02：

[2021/02/22 13:43:35.535 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=113889] [currIdx=2] [leaderStoreID=2]
[2021/02/22 13:43:35.535 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=113945] [currIdx=2] [leaderStoreID=2]
[2021/02/22 13:43:36.264 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=113885] [currIdx=2] [leaderStoreID=2]
[2021/02/22 13:43:39.538 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=113861] [currIdx=2] [leaderStoreID=2]
[2021/02/22 13:43:42.848 +08:00] [INFO] [coprocessor.go:1034] ["[TIME_COP_PROCESS] resp_time:301.596624ms txnStartTS:423093239163650052 region_id:113769 store_addr:172.18.163.111:20160 kv_process_ms:300 scan_total_write:258213 scan_processed_write:256722 scan_total_data:257847 scan_processed_data:256520 scan_total_lock:1 scan_processed_lock:0"] [conn=27744913]
[2021/02/22 13:43:46.127 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=124997] [currIdx=2] [leaderStoreID=2]
[2021/02/22 13:43:46.434 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=97805] [currIdx=0] [leaderStoreID=2]
[2021/02/22 13:43:48.069 +08:00] [INFO] [adapter.go:621] ["pessimistic write conflict, retry statement"] [conn=27745034] [txn=423093240553013288] [forUpdateTS=423093240605442061] [err="[kv:9007]Write conflict, txnStartTS=423093240553013288, conflictStartTS=423093240553013293, conflictCommitTS=423093240605442066, key={tableID=24073, handle=0} primary={tableID=25721, handle=275285} [try again later]"]
[2021/02/22 13:44:00.264 +08:00] [WARN] [client_batch.go:638] ["wait response is cancelled"] [to=172.18.163.112:20160] [cause="context canceled"]
[2021/02/22 13:44:00.264 +08:00] [WARN] [client_batch.go:638] ["wait response is cancelled"] [to=172.18.163.112:20160] [cause="context canceled"]
[2021/02/22 13:44:00.264 +08:00] [WARN] [client_batch.go:638] ["wait response is cancelled"] [to=172.18.163.112:20160] [cause="context canceled"]
[2021/02/22 13:44:00.264 +08:00] [WARN] [client_batch.go:638] ["wait response is cancelled"] [to=172.18.163.112:20160] [cause="context canceled"]
[2021/02/22 13:44:00.264 +08:00] [WARN] [client_batch.go:638] ["wait response is cancelled"] [to=172.18.163.112:20160] [cause="context canceled"]
[2021/02/22 13:44:14.819 +08:00] [INFO] [set.go:213] ["set global var"] [conn=27745000] [name=tidb_auto_analyze_ratio] [val=0.2]
[2021/02/22 13:44:22.533 +08:00] [INFO] [set.go:213] ["set global var"] [conn=27745000] [name=tidb_auto_analyze_start_time] [val="01:00 +0800"]
[2021/02/22 13:44:27.309 +08:00] [INFO] [set.go:213] ["set global var"] [conn=27745000] [name=tidb_auto_analyze_end_time] [val="05:00 +0800"]
[2021/02/22 13:44:31.139 +08:00] [INFO] [adapter.go:621] ["pessimistic write conflict, retry statement"] [conn=27745920] [txn=423093251838312534] [forUpdateTS=423093251890741322] [err="[kv:9007]Write conflict, txnStartTS=423093251838312534, conflictStartTS=423093251851419684, conflictCommitTS=423093251890741380, key={tableID=24073, handle=0} primary={tableID=24211, handle=289167} [try again later]"]
[2021/02/22 13:44:34.320 +08:00] [WARN] [client_batch.go:638] ["wait response is cancelled"] [to=172.18.163.112:20160] [cause="context canceled"]
[2021/02/22 13:44:34.320 +08:00] [WARN] [client_batch.go:638] ["wait response is cancelled"] [to=172.18.163.113:20160] [cause="context canceled"]
[2021/02/22 13:44:34.320 +08:00] [WARN] [client_batch.go:638] ["wait response is cancelled"] [to=172.18.163.112:20160] [cause="context canceled"]
[2021/02/22 13:44:55.826 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=100565] [currIdx=1] [leaderStoreID=7]
[2021/02/22 13:44:55.826 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=100565] [currIdx=1] [leaderStoreID=7]
[2021/02/22 13:44:55.826 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=100565] [currIdx=1] [leaderStoreID=7]
[2021/02/22 13:45:00.186 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=113369] [currIdx=0] [leaderStoreID=2]
[2021/02/22 13:45:00.432 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=111873] [currIdx=0] [leaderStoreID=2]
[2021/02/22 13:45:00.433 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=111873] [currIdx=0] [leaderStoreID=2]
[2021/02/22 13:45:00.541 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=111569] [currIdx=0] [leaderStoreID=2]
[2021/02/22 13:45:02.416 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=98821] [currIdx=1] [leaderStoreID=1]
[2021/02/22 13:45:08.946 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=124361] [currIdx=0] [leaderStoreID=7]
[2021/02/22 13:45:16.126 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=125145] [currIdx=2] [leaderStoreID=2]
[2021/02/22 13:45:18.714 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=116545] [currIdx=1] [leaderStoreID=7]
[2021/02/22 13:45:20.085 +08:00] [INFO] [region_cache.go:839] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=113857] [currIdx=2] [leaderStoreID=2]

Kongdom · 2021 年2 月 22 日 06:28

我这边设置自动analyze table的时候，也遇到过8小时时差的时区问题，当时只是将目标时间提前了8小时就可以了

来了老弟 · 2021 年2 月 22 日 06:33

这种办法也是可以的：
374a4260-0b1e-4b70-82d7-7b9db7eea6a3

酱紫设置，

或者直接调整集群和系统时区保持一致。

Kongdom · 2021 年2 月 22 日 08:49

原来是这样啊，我之前就觉得加号后面应该是时区，当时没跟客户纠结，直接把目标时间减去8小时设置的。

zhimadi · 2021 年2 月 22 日 09:00

我这边设置的时候有指定时区，但还是跟结果不相符。

来了老弟 · 2021 年2 月 23 日 02:50

辛苦展示下你的操作。

zhimadi · 2021 年2 月 23 日 07:07

你好，就帖子上面的【问题描述】，详细的操作过程。

yilong · 2021 年2 月 23 日 08:17

感觉可以确认下操作系统的时区，看看是否和当前你所处时区一致。

zhimadi · 2021 年2 月 23 日 08:31

操作前有确认，是东八区Tue, 23 Feb 2021 16:30:45 +0800

yilong · 2021 年2 月 24 日 03:05

可以帮忙确认下目前的执行时间都是什么时间段吗？是24小时任意，还是在某个4小时时间段内？

yilong · 2021 年3 月 4 日 06:43

您好，请参考下这个帖子，是否因为这些表之前从来都没有analyze 过，多谢。