Bug #50620 Adding an index to a table prevents slave from logging into slow log
Submitted: 26 Jan 2010 11:36 Modified: 21 Jun 2010 0:51
Reporter: Luis Soares Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.5.99, next-mr, 5.1 OS:Any
Assigned to: Luis Soares CPU Architecture:Any
Tags: slave, slow log
Triage: Triaged: D3 (Medium)

[26 Jan 2010 11:36] Luis Soares
Description:
Adding an index to a table makes the slave not to log into the
slow log anymore.

This bug seems to be deterministic and caused by the following
sequence of events (in pseudo-SQL and assuming that slow_log
destination in both master and slave is 'TABLE'):

MASTER> CREATE TABLE t1
MASTER> INSERT long_query1 INTO t1
MASTER> ALTER TABLE t1 ADD INDEX idx
MASTER> INSERT long_query1 INTO t1
MASTER> SELECT FROM mysql.slow_log
2 entries
... wait for slave to catch up (sync with master)

SLAVE> SELECT FROM mysql.slow_log
1 entry < ----- Where did the second (long) INSERT go?

======= // ========

This bug was spotted on mysql-next-mr.
Revision details:

  - revno: 2965
  - revision-id: alik@sun.com-20100125161225-mpr7xlu4kvx45e1i
  - timestamp: Mon 2010-01-25 19:12:25 +0300

How to repeat:
1. Setting up:

$ bzr clone -rrevid:alik@sun.com-20100125161225-mpr7xlu4kvx45e1i $YOUR_REPO/mysql-next-mr 
$ cd mysql-next-mr
$ bash BUILD/compile-pentium64-debug-max
$ cd mysql-test

2. Create an MTR test file (lets name it suite/rpl/t/rpl_slow.test):

-- source include/master-slave.inc
-- source include/have_binlog_format_statement.inc

CALL mtr.add_suppression("Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT");

SET @old_log_output= @@log_output;
SET GLOBAL log_output= 'TABLE';
SET GLOBAL long_query_time= 2;
SET @old_long_query_time= @@long_query_time;
SET SESSION long_query_time= 2;
TRUNCATE mysql.slow_log;

-- connection slave
-- source include/stop_slave.inc
SET @old_log_output= @@log_output;
SET GLOBAL log_output= 'TABLE';
SET @old_long_query_time= @@long_query_time;
SET GLOBAL long_query_time= 2;
TRUNCATE mysql.slow_log;
-- source include/start_slave.inc

-- echo ********************************************************************
-- echo **** INSERT two rows, one exceeds long_query_time and other does not
-- echo **** Outcome: long query ends up in both master and slave slow log
-- echo ********************************************************************

-- connection master
CREATE TABLE t1 (a int, b int); 

-- let $slow_query= INSERT INTO t1 values(1, sleep(3))
-- let $fast_query= INSERT INTO t1 values(1, 1)

-- disable_warnings
-- eval $fast_query
-- eval $slow_query
-- enable_warnings

-- echo *** MASTER ***
SELECT * FROM mysql.slow_log;

-- sync_slave_with_master
-- echo *** SLAVE ***
SELECT * FROM mysql.slow_log;

-- echo ******************************************************************
-- echo **** Now do inserts again, but first add an index to the table.
-- echo **** Outcome: Note the absence of entries in slave slow log table.
-- echo ******************************************************************

TRUNCATE mysql.slow_log;
-- connection master
TRUNCATE mysql.slow_log;

ALTER TABLE t1 ADD INDEX id1(a);

-- disable_warnings
-- eval $fast_query
-- eval $slow_query
-- enable_warnings

-- echo *** MASTER ***
SELECT * FROM mysql.slow_log;

-- sync_slave_with_master
-- echo *** SLAVE ***
SELECT * FROM mysql.slow_log;

-- connection master
SET @@global.log_output= @old_log_output;
SET @@global.long_query_time= @old_long_query_time;
DROP TABLE t1;

-- sync_slave_with_master
SET @@global.log_output= @old_log_output;
SET @@global.long_query_time= @old_long_query_time;

-- exit

3. Run the test case with:

mysql-test$ perl mysql-test-run.pl --mysqld=--log-slow-slave-statements rpl.rpl_slow

Suggested fix:
n/a
[26 Jan 2010 11:40] Luis Soares
For the test case in the how to repeat section, I find that running
it with:

./mtr --mysqld=--log-slow-slave-statements --mysqld=--log-slow-admin-statements rpl.rpl_slow

Makes the slave to log the slow statements even after adding the index.
[26 Jan 2010 11:52] Sveta Smirnova
Verified as described.
[26 Jan 2010 16:26] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/98219

2977 Luis Soares	2010-01-26
      BUG#50620: Adding an index to a table prevents slave from logging
      into slow log
      
      While processing a statement, down the mysql_parse execution
      stack, the thd->enable_slow_log can be assigned to
      opt_log_slow_admin_statements, depending whether one is executing
      administrative statements, such as ALTER TABLE, OPTIMIZE,
      ANALYZE, etc, or not. This can have an impact on slow logging for
      statements that are executed after an administrative statement
      execution is completed.
      
      When executing statements directly from the user this is fine
      because, the thd->enable_slow_log is reset right at the beginning
      of the dispatch_command function, ie, everytime a new statement
      is set is set to execute.
      
      On the other hand, for slave SQL thread (sql_thd) the story is a
      bit different. When in SBR the sql_thd applies statements by
      calling mysql_parse. Right after, it calls log_slow_statement
      function to log them if they take too long. Calling mysql_parse
      directly is fine, but also means that dispatch_command function
      is bypassed. As a consequence, thd->enable_slow_log does not get
      a chance to be reset before the next statement to be executed by
      the sql_thd. If the statement just executed by the sql_thd was an
      administrative statement and logging of admin statements was
      disabled, this means that sql_thd->enable_slow_log will be set to
      0 (disabled) from that moment on. End result: sql_thd stops
      logging slow statements.
      
      We fix this by resetting the value of sql_thd->enable_slow_log to
      the value of opt_log_slow_slave_statements right after
      log_slow_stement is called by the sql_thd.
[5 Feb 2010 17:48] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/99509

3368 Luis Soares	2010-02-05
      BUG#50620: Adding an index to a table prevents slave from logging
      into slow log
            
      While processing a statement, down the mysql_parse execution
      stack, the thd->enable_slow_log can be assigned to
      opt_log_slow_admin_statements, depending whether one is executing
      administrative statements, such as ALTER TABLE, OPTIMIZE,
      ANALYZE, etc, or not. This can have an impact on slow logging for
      statements that are executed after an administrative statement
      execution is completed.
            
      When executing statements directly from the user this is fine
      because, the thd->enable_slow_log is reset right at the beginning
      of the dispatch_command function, ie, everytime a new statement
      is set is set to execute.
            
      On the other hand, for slave SQL thread (sql_thd) the story is a
      bit different. When in SBR the sql_thd applies statements by
      calling mysql_parse. Right after, it calls log_slow_statement
      function to log them if they take too long. Calling mysql_parse
      directly is fine, but also means that dispatch_command function
      is bypassed. As a consequence, thd->enable_slow_log does not get
      a chance to be reset before the next statement to be executed by
      the sql_thd. If the statement just executed by the sql_thd was an
      administrative statement and logging of admin statements was
      disabled, this means that sql_thd->enable_slow_log will be set to
      0 (disabled) from that moment on. End result: sql_thd stops
      logging slow statements.
            
      We fix this by resetting the value of sql_thd->enable_slow_log to
      the value of opt_log_slow_slave_statements right after
      log_slow_stement is called by the sql_thd.
[1 Mar 2010 8:47] Bugs System
Pushed into 5.1.45 (revid:joro@sun.com-20100301083827-xnimmrjg6bh33o1o) (version source revid:joerg@mysql.com-20100212173307-ph563zr4wmoklgwd) (merge vers: 5.1.45) (pib:16)
[1 Mar 2010 13:53] Jon Stephens
Documented bugfix in the 5.1.45 changelog as follows:

        Adding an index to a table on the master caused the slave to
        stop logging slow queries to the slow query log.

Set NM status, waiting for merges to later trees.
[2 Mar 2010 14:34] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100302142746-u1gxdf5yk2bjrq3e) (version source revid:alik@sun.com-20100225090938-2j5ybqoau570mytu) (merge vers: 6.0.14-alpha) (pib:16)
[2 Mar 2010 14:39] Bugs System
Pushed into 5.5.3-m2 (revid:alik@sun.com-20100302072233-t3uqgjzdukt1pyhe) (version source revid:alexey.kopytov@sun.com-20100209075938-mmcnyf6w631ozc45) (merge vers: 5.5.2-m2) (pib:16)
[2 Mar 2010 14:44] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100302072432-k8xvfkgcggkwgi94) (version source revid:alik@sun.com-20100224135227-rcqs9pe9b2in80pf) (pib:16)
[3 Mar 2010 5:05] Jon Stephens
Also documented in the 5.5.3 and 6.0.14 changelogs; closed.
[17 Jun 2010 12:00] Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:41] Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609140708-52rvuyq4q500sxkq) (merge vers: 5.1.45-ndb-6.2.19) (pib:16)
[17 Jun 2010 13:28] Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)