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.
