| 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: | |
| 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 | ||
[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)
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