In this blog post, I’ll talk about multi-threaded slave statistics printed in MySQL error log file.

MySQL version 5.6 and later allows you to execute replicated events using parallel threads. This feature is called Multi-Threaded Slave (MTS), and to enable it you need to modify the

slave_parallel_workers

 variable to a value greater than 1.

Recently, a few customers asked about the meaning of some new statistics printed in their error log files when they enable MTS. These error messages look similar to the example stated below:

[Note] Multi-threaded slave statistics for channel '': seconds elapsed = 123; events assigned = 57345; worker queues filled over overrun level = 0; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 0 waited (count) …

Performance Schema

In many types of database workloads, using a multi-threaded slave from 5.6+ helps improve replication performance. I’ve had a number of users enable this feature, but have not seen anyone ask how each thread is performing. Here’s a quick way with Performance_Schema to measure the amount of multi-threaded slave activity on each thread (after you have already configured MTS on your slave of course ).

First, we need to enable the 

statements

 instruments:

slave1> UPDATE setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE 'events_statements_%';
Query OK, 2 rows affected (0.00 sec)
Rows matched: 3  Changed: 2  Warnings: 0

Next, let’s find the

THREAD_ID

 for our slave workers:

slave1> SELECT THREAD_ID, …

MySQL 5.6 allows you to execute replicated events in parallel as long as data is split across several databases. This feature is named “Multi-Threaded Slave” (MTS) and it is easy to enable by setting slave_parallel_workers to a > 1 value. However if you decide to use MTS without GTIDs, you may run into annoying issues. Let’s look at two of them.

Skipping replication errors

When replication stops with an error, a frequent approach is to “ignore now and fix later.” This means you will run SET GLOBAL sql_slave_skip_counter=1 to be able to restart replication as quickly as possible and later use pt-table-checksum/pt-table-sync to resync data on the slave.

Then the day when I hit:

mysql> show slave status;
[...]
Last_SQL_Error: Worker 0 failed executing transaction '' at master log mysql-bin.000017, end_log_pos 1216451; Error 'Duplicate entry '1001' for key 'PRIMARY'' on query. …

Have you ever wondered exactly does log_warnings=2 log? Well, I have, and finally decided to check the code. (The manual used to mention setting this to 2 for diagnosing some connection-related problems, but I didn’t run into that comment in my most recent search.)

Basically, in recent 5.6 source code, we find “log_warnings > 1″ in 7 files. In 5.5 source, it is only in 5 files. Here are the 7 files in 5.6:

filesort.cc (line 460)
log_event.cc (lines 4873, 10020, 11209)
rpl_master.cc (line 912)
rpl_rli_pdb.cc (lines 1538, 1596, 1735, 2066)
rpl_slave.cc (lines 3585, 4684, 5405, 5436)
sql_acl.cc (lines 9591, 9613, 11351)
sql_connect.cc (line 791)

Long story short, the main (most common) ones are when a filesort fails (filesort.cc) or a failed login occurs (sql_acl.cc). Then there are some replication-specific instances where it logs extra info, such as master/slave/binlog info, “ignored” errors, and some summary stats …