Bug #93034 replication logging - please move to performance_schema

Submitted: 31 Oct 2018 18:24 Modified: 5 Oct 2022 7:18
Reporter: Simon Mudd Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S4 (Feature request)
Version:8.0.13 OS:Any
Assigned to: CPU Architecture:Any
Tags: logging, performance_schema, replication

[31 Oct 2018 18:24] Simon Mudd
Description:
I see these logs in my system every 2 minutes:

2018-10-31T17:52:42.509623Z 5 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel '': seconds elapsed = 121; events assigned = 12525569; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 2730510184400 waited (count) when Workers occupied = 0 waited when Workers occupied = 0
2018-10-31T17:54:43.617469Z 5 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel '': seconds elapsed = 121; events assigned = 12592129; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 2744546840600 waited (count) when Workers occupied = 0 waited when Workers occupied = 0
2018-10-31T17:56:43.001382Z 5 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel '': seconds elapsed = 120; events assigned = 12658689; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 2759298694200 waited (count) when Workers occupied = 0 waited when Workers occupied = 0
2018-10-31T17:58:43.785779Z 5 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel '': seconds elapsed = 120; events assigned = 12759041; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 2780638594600 waited (count) when Workers occupied = 0 waited when Workers occupied = 0
2018-10-31T18:00:44.268489Z 5 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel '': seconds elapsed = 121; events assigned = 12834817; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 2797422939800 waited (count) when Workers occupied = 0 waited when Workers occupied = 0

This is noisy and not easy to read. Docs on the MySQL web site don't help much. I got pointed at https://www.percona.com/blog/2017/07/19/multi-threaded-slave-statistics/ which helps a lot more.  Thanks JF.

$ sudo grep -c MY-010559 /var/log/mysqld.log
200

not been running long but it’s noisy.

How to repeat:
setup replication, at least with write set and watch the noise.
Then wonder what it means.

Suggested fix:
1. At least i can turn off the noise with dragnet logging
2. However the information is useful. Please expose this via a performance_schema table.
3. If you don't stop the logging make the display interval configurable, including setting it to 0 meaning don't show anything.
4. Improve the documentation to mention this output or the P_S table if you create one so it can be better understood as https://dev.mysql.com/doc/refman/8.0/en/error-messages-server.html does not help.
[9 Nov 2018 12:33] MySQL Verification Team
Hello Simon,

Thank you for the feature request!

regards,
Umesh
[28 Dec 2018 11:15] Amit Wadkar
I'm also facing this issue in 5.7.17 with MTS(Multi Thread slave)
[26 Mar 2019 12:06] Simon Mudd
FWIW in 8.0 you can make this go away. 

Load the dragnet filter and run:

SET GLOBAL log_error_services='log_filter_dragnet; log_sink_internal';
SET GLOBAL dragnet.log_error_filter_rules='IF err_code == 10559 then drop.';
[5 Oct 2022 4:50] Shane Bester
To suppress this spam:

[mysqld]
log_error_suppression_list='MY-010559'
[5 Oct 2022 7:16] Simon Mudd
Indeed, but log_error_suppression_list was not available when I opened this bug report.

However, the new setting does help filter out such entries.
[5 Oct 2022 7:18] Simon Mudd
Actually I'm wrong.

https://dev.mysql.com/doc/refman/8.0/en/server-system-variables.html indicates it was released in 8.0.13. I believe I'd seen this previously and had not seen this new setting when I reported the issue.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.057 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.