Bug #95422 MY-010956 and MY-010957 are possible too noisy in error-log
Submitted: 20 May 2019 7:40 Modified: 22 May 2019 4:41
Reporter: tsubasa tanaka (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S4 (Feature request)
Version:8.0.15 OS:CentOS (7.4)
Assigned to: CPU Architecture:x86

[20 May 2019 7:40] tsubasa tanaka
Description:
This is feature request.

MY-010956(Logging when original_commit_timestamp > immediate_commit_timestamp) and MY-010957(Logging when backing to immediate_commit_timestamp <= original_commit_timestamp after MY-010956 occurred) are possible too noisy in error-log.

MYSQL_BIN_LOG::write_gtid compares micro-sec level timestamp "original_commit_timestamp" and "immediate_commit_timestamp" (https://github.com/mysql/mysql-server/blob/mysql-8.0.16/sql/binlog.cc#L1526-L1539)

But they can have difference between master's system-time and slave's system-time in micro-sec order in real world.

Example, in our production, both master and slave use NTP time-sync but they have system-time difference about 500us.

How to repeat:
Prepare 2 servers which have 500us system-time difference.

```
$ date "+%s.%N" ### at master
1558337325.766668654

$ date "+%s.%N" ### at slave
1558337325.767114036
```

Setting up replication environment and start slave, slave mysqld dumps too noisy logs in error-log.

2019-05-20T14:25:17.121864+09:00 5 [Warning] [MY-010956] [Server] Invalid replication timestamps: original commit timestamp is more recent than the immediate commit timestamp. This may be an issue if delayed replication is active. Make sure that servers have their clocks set to the correct time. No further message will be emitted until after timestamps become valid again.
2019-05-20T14:25:17.177804+09:00 5 [Warning] [MY-010957] [Server] The replication timestamps have returned to normal values.

Suggested fix:
Please add a margin of time for MY-010956.

Sample implement, following code adds a margin of "binlog_timestamp_warning_threshold" milli-seconds to logging.

---
diff -r mysql-8.0.16_orig/sql/binlog.cc mysql-8.0.16/sql/binlog.cc
1528c1528
<     if (original_commit_timestamp > immediate_commit_timestamp &&
---
>     if (original_commit_timestamp > immediate_commit_timestamp + thd->variables.binlog_timestamp_warning_threshold * 1000 &&
---
[20 May 2019 7:43] tsubasa tanaka
Or, tone down MY-010956 and MY-010957 to INFO-level log.
After that, I can filter them by setting log_error_verbosity :)
[22 May 2019 4:41] MySQL Verification Team
Hello Tanaka-San,

Thank you for the feature request!

regards,
Umesh