MySQL Bugs: #95422: MY-010956 and MY-010957 are possible too noisy in error-log

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

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 &&
---

Or, tone down MY-010956 and MY-010957 to INFO-level log.
After that, I can filter them by setting log_error_verbosity :)

Hello Tanaka-San,

Thank you for the feature request!

regards,
Umesh

Should be able to filter specific messages using

https://dev.mysql.com/doc/refman/8.0/en/server-system-variables.html#sysvar_log_error_supp...

or throttle them with "dragnet"

https://dev.mysql.com/doc/refman/8.0/en/error-log-rule-based-filtering.html

After 2 years the rather simple issue is still present.
It's very annoying to have logs full of this because of nanosecond difference in clocks.
Could we please add a margin for difference or ability to turn this off / filter out?
Thanks!

Haven't seen it so frequently before MySQL 8.

Is there a possibility to turn this logging event off?