When performing scheduled task backups with BR, the start time for executing the BR backup command is 03:30, and the completion time is 06:12. [BackupTS=443943256514101256] Why is it 03:12?

Translated
1

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

Original topic: br做定时任务备份时，开始执行br备份命令的时间为：03：30分，备份完成的时间：06：12分,[BackupTS=443943256514101256] 为啥是03：12

| username: vcdog

[TiDB Usage Environment] Production Environment
[TiDB Version] v6.5.0
[Reproduction Path] Operations performed that led to the issue
[Encountered Issue: Problem Phenomenon and Impact] When performing scheduled backups with BR, the BR backup command starts at 03:30 and completes at 06:12. [BackupTS=443943256514101256] Why is it 03:12? Below is the log content at the time of backup completion:

[2023/09/01 06:12:41.357 +08:00] [INFO] [collector.go:74] ["Database Backup success summary"] [total-ranges=39219] [ranges-succeed=39219] [ranges-failed=0] [backup-checksum=10m11.975870303s] [backup-fast-checksum=121.888421ms] [backup-total-ranges=6115] [total-take=2h42m37.988144254s] [total-kv-size=2.736TB] [average-speed=280.4MB/s] [backup-data-size(after-compressed)=378.1GB] [Size=378090324122] [BackupTS=443943256514101256] [total-kv=12114883615]

[Resource Configuration]
[Attachments: Screenshots/Logs/Monitoring]

2
| username: vcdog | Original post link 
mysql>  SELECT TIDB_PARSE_TSO('443943256514101256');
+--------------------------------------+
| TIDB_PARSE_TSO('443943256514101256') |
+--------------------------------------+
| 2023-09-01 03:12:06.717000           |
+--------------------------------------+
1 row in set (0.02 sec)
3
| username: 像风一样的男子 | Original post link

Did you specify TSO in your backup command?

4
| username: dba-kit | Original post link

Could you send the BR execution command?

5
| username: vcdog | Original post link

The above code is the backup command in the backup script and does not specify the exact snapshot time point of the TSO.

6
| username: 有猫万事足 | Original post link

Check if NTP is synchronized by running:

tiup cluster exec <cluster-name> --command='ntpstat'
7
| username: tidb菜鸟一只 | Original post link

Just look in the logs for when BackupTS was first generated. It is usually the time when you started executing the br command. If a specific time was specified in the command, then it will be the specified time…

8
| username: vcdog | Original post link

The NTP time on the servers should be fine.

9
| username: TiDBer_QYr0vohO | Original post link

I just checked, and the execution time of my backup command roughly matches the parsed TSO time.

10
| username: vcdog | Original post link

This is the value of BackupTS that first appeared in the backup log.

This is the value of BackupTS that appeared at the end of the backup log.

These two TSO are for the same time:

mysql>  SELECT TIDB_PARSE_TSO('443943256514101256');
+--------------------------------------+
| TIDB_PARSE_TSO('443943256514101256') |
+--------------------------------------+
| 2023-09-01 03:12:06.717000           |
+--------------------------------------+
1 row in set (0.02 sec)
11
| username: tidb菜鸟一只 | Original post link

Check what time it is on your PD server right now…

12
| username: zhanggame1 | Original post link

Query the time on all cluster nodes.

13
| username: vcdog | Original post link

The expert is indeed an expert. There are indeed 2 PDs whose time is 18 minutes later than the current time. What is the rule for this [BackupTS=443943256514101256]? Does it take the time of the PD that is the earliest?

14
| username: 像风一样的男子 | Original post link

TSO is generated by the leader of PD.

15
| username: tidb菜鸟一只 | Original post link

Check the time of the PD leader. Use tiup cluster display tidb-xxx to see if the machine where the PD leader is located has a slower time.

16
| username: vcdog | Original post link

I just modified the time on those 2 PD nodes and then executed tiup cluster display tidb-xxx, which directly reported an error and couldn’t display:

tiup is checking updates for component cluster ...
A new version of cluster is available:
   The latest version:         v1.13.0
   Local installed version:    v1.12.2
   Update current component:   tiup update cluster
   Update all components:      tiup update --all

Error: stat .: resource temporarily unavailable

This error persisted for a while. Currently, when I execute tiup cluster display tidb-xxx again, it is normal.

17
| username: vcdog | Original post link

In the past, I remember we unified the time modification using NTP synchronization. Mainly, our TiDB components are deployed in virtual machines. After a period of time, the time might automatically change again.

18
| username: vcdog | Original post link

This time, I have uniformly adjusted the time. Let’s observe the situation for a few more days.

19
| username: cassblanca | Original post link

You need to check the NTP server and hardware clock settings to see why the time is not automatically calibrated.

20
| username: zhanggame1 | Original post link

No matter what cluster you install, NTP must be configured properly, otherwise, problems are likely to occur. If there is a time difference in the TiDB cluster, there will be a large number of records in the logs.