Bug #74233 Slave's slow log has empty BEGINs for RBR events
Submitted: 6 Oct 2014 10:40 Modified: 21 Jul 2017 13:21
Reporter: Przemyslaw Malkowski Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.6.22,5.5 5.6 OS:Any
Assigned to: CPU Architecture:Any
Tags: log_slow_slave_statements ROW slow_log

[6 Oct 2014 10:40] Przemyslaw Malkowski
Description:
When the log_slow_slave_statements is enabled on slave, it only logs properly events in STATEMENT mode, while for RBR one only an empty "BEGIN;" gets logged.

Also the documentation does not mention that:
http://dev.mysql.com/doc/refman/5.6/en/replication-options-slave.html#sysvar_log_slow_slav...

How to repeat:
master [localhost] {msandbox} (test) > select @@version,@@version_comment;
+------------+------------------------------+
| @@version  | @@version_comment            |
+------------+------------------------------+
| 5.6.21-log | MySQL Community Server (GPL) |
+------------+------------------------------+
1 row in set (0.00 sec)

master [localhost] {msandbox} (test) > select @@binlog_format;
+-----------------+
| @@binlog_format |
+-----------------+
| MIXED           |
+-----------------+
1 row in set (0.00 sec)

slave1 [localhost] {msandbox} (test) > show variables like '%slow%';
+---------------------------+-------------------------------------------------------------------------+
| Variable_name             | Value                                                                   |
+---------------------------+-------------------------------------------------------------------------+
| log_slow_admin_statements | OFF                                                                     |
| log_slow_slave_statements | ON                                                                      |
| slow_launch_time          | 2                                                                       |
| slow_query_log            | ON                                                                      |
| slow_query_log_file       | /home/przemek/sandboxes/rsandbox_mysql-5_6_21/node1/data/pmlap-slow.log |
+---------------------------+-------------------------------------------------------------------------+
5 rows in set (0.00 sec)

slave1 [localhost] {msandbox} ((none)) > select @@long_query_time;
+-------------------+
| @@long_query_time |
+-------------------+
|          0.000000 |
+-------------------+
1 row in set (0.00 sec)

master [localhost] {msandbox} ((none)) > create table test.t1 (id int auto_increment primary key);
Query OK, 0 rows affected (0.33 sec)

master [localhost] {msandbox} ((none)) > insert into test.t1 values (1);
Query OK, 1 row affected (0.08 sec)

master [localhost] {msandbox} ((none)) > insert into test.t1 values (2);
Query OK, 1 row affected (0.18 sec)

master [localhost] {msandbox} ((none)) > delete from test.t1 limit 1;
Query OK, 1 row affected (0.04 sec)

master [localhost] {msandbox} ((none)) > insert into test.t1 values (3);
Query OK, 1 row affected (0.20 sec)

slave1 [localhost] {msandbox} ((none)) > show binlog events in 'mysql-bin.000003';
+------------------+------+-------------+-----------+-------------+----------------------------------------------------------+
| Log_name         | Pos  | Event_type  | Server_id | End_log_pos | Info                                                     |
+------------------+------+-------------+-----------+-------------+----------------------------------------------------------+
| mysql-bin.000003 |    4 | Format_desc |       101 |         120 | Server ver: 5.6.21-log, Binlog ver: 4                    |
| mysql-bin.000003 |  120 | Query       |         1 |         246 | create table test.t1 (id int auto_increment primary key) |
| mysql-bin.000003 |  246 | Query       |         1 |         321 | BEGIN                                                    |
| mysql-bin.000003 |  321 | Query       |         1 |         421 | insert into test.t1 values (1)                           |
| mysql-bin.000003 |  421 | Xid         |         1 |         452 | COMMIT /* xid=30 */                                      |
| mysql-bin.000003 |  452 | Query       |         1 |         527 | BEGIN                                                    |
| mysql-bin.000003 |  527 | Query       |         1 |         627 | insert into test.t1 values (2)                           |
| mysql-bin.000003 |  627 | Xid         |         1 |         658 | COMMIT /* xid=32 */                                      |
| mysql-bin.000003 |  658 | Query       |         1 |         721 | BEGIN                                                    |
| mysql-bin.000003 |  721 | Table_map   |         1 |         766 | table_id: 71 (test.t1)                                   |
| mysql-bin.000003 |  766 | Delete_rows |         1 |         806 | table_id: 71 flags: STMT_END_F                           |
| mysql-bin.000003 |  806 | Xid         |         1 |         837 | COMMIT /* xid=34 */                                      |
| mysql-bin.000003 |  837 | Query       |         1 |         912 | BEGIN                                                    |
| mysql-bin.000003 |  912 | Query       |         1 |        1012 | insert into test.t1 values (3)                           |
| mysql-bin.000003 | 1012 | Xid         |         1 |        1043 | COMMIT /* xid=36 */                                      |
+------------------+------+-------------+-----------+-------------+----------------------------------------------------------+
15 rows in set (0.00 sec)

slave1 [localhost] {msandbox} ((none)) > \! cat /home/przemek/sandboxes/rsandbox_mysql-5_6_21/node1/data/pmlap-slow.log
/home/sandbox/tarballs/5.6.21/bin/mysqld, Version: 5.6.21-log (MySQL Community Server (GPL)). started with:
Tcp port: 20887  Unix socket: /tmp/mysql_sandbox20887.sock
Time                 Id Command    Argument
# Time: 141006 12:33:24
# User@Host: msandbox[msandbox] @ localhost []  Id:     6
# Query_time: 0.707058  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591604;
flush logs;
# Time: 141006 12:33:33
# User@Host: [] @  []  Id:     5
# Query_time: 0.399336  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591613;
create table test.t1 (id int auto_increment primary key);
# Time: 141006 12:33:39
# User@Host: [] @  []  Id:     5
# Query_time: 0.000031  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591619;
BEGIN;
# User@Host: [] @  []  Id:     5
# Query_time: 0.000779  Lock_time: 0.000590 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591619;
insert into test.t1 values (1);
# Time: 141006 12:33:45
# User@Host: [] @  []  Id:     5
# Query_time: 0.000048  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591625;
BEGIN;
# User@Host: [] @  []  Id:     5
# Query_time: 0.000300  Lock_time: 0.000089 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591625;
insert into test.t1 values (2);
# Time: 141006 12:34:00
# User@Host: [] @  []  Id:     5
# Query_time: 0.000025  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591640;
BEGIN;
# Time: 141006 12:34:05
# User@Host: [] @  []  Id:     5
# Query_time: 0.000042  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591645;
BEGIN;
# User@Host: [] @  []  Id:     5
# Query_time: 0.000295  Lock_time: 0.000116 Rows_sent: 0  Rows_examined: 0
SET timestamp=1412591645;
insert into test.t1 values (3);

Suggested fix:
Allow logging ROW based events in the slave's slow log, or at least do not log empty BEGINs and make clear in the documentation that this is not possible to see RBR events in slave's slow log.
[7 Oct 2014 12:01] Umesh Shastry
Hello Przemyslaw,

Thank you for the bug report and test case.
Indeed, "delete" is missing from slave's slow query log.

Thanks,
Umesh
[7 Oct 2014 12:12] Umesh Shastry
test results

Attachment: 74233.txt (text/plain), 9.58 KiB.

[6 Sep 2016 1:13] Agustín G
Hi,

A simple heads-up in the documentation (https://dev.mysql.com/doc/refman/5.6/en/replication-options-slave.html#sysvar_log_slow_sla...) will help a lot here. I was some time debugging this today until I noticed that it was because of RBR queries. Just adding something like the following will make a big difference:

"Note that some statements logged using row-based replication in the master will not be logged in the slave's slow log, even if log_slow_slave_statements is enabled."

Thanks!
[23 Mar 2017 10:09] Jörg Brühe
This is still not documented in the manual, page "The Slow Query Log", for any version (5.5, 5.6).
Given that this is verified for more than 2 years now, I'm disappointed.
[21 Jul 2017 13:21] Margaret Fisher
Posted by developer:
 
I've been tasked with clearing up some old doc bugs that were in the wrong pile. I've made this documentation change in 5.5 and up, where it should be showing soon at
https://dev.mysql.com/doc/refman/5.6/en/replication-options-slave.html#sysvar_log_slow_sla...
(and equivalents in other releases).
The text as revised by development is:
Note that all statements logged in row format in the master will not be logged in the slave's slow log, even if log_slow_slave_statements is enabled.
[26 Jul 2017 22:46] Agustín G
Looks good, Margaret. Thanks!