| Bug #23300 | Slow query log on slave does not log slow replicated statements | ||
|---|---|---|---|
| Submitted: | 15 Oct 2006 6:00 | Modified: | 21 Jun 2010 0:48 |
| Reporter: | Morgan Tocker | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 4.1+ | OS: | Any (*) |
| Assigned to: | Luis Soares | CPU Architecture: | Any |
[15 Oct 2006 18:26]
MySQL Verification Team
verified on 5.0.26
Master: (--long_query_time=5 --log-slow-queries)
# Query_time: 27 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
use test;
UPDATE index_test SET a=REPEAT('A', 50);
Slave: (--long_query_time=5 --log-slow-queries)
Tcp port: 3306 Unix socket: (null)
Time Id Command Argument
[23 Oct 2008 15:20]
Lars Thalmann
See also BUG#27492.
[23 Oct 2008 15:39]
Lars Thalmann
Jon, please document the current behaviour. After doing this, set the bug report back to "verified". We will probably fix this in a later version, but not in 5.1 and below.
[24 Oct 2008 16:44]
Jon Stephens
Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly, and will be included in the next release of the relevant products. Docs update: http://lists.mysql.com/commits/57034
[24 Oct 2008 16:46]
Jon Stephens
Set bug category/status to Replication/Verified following docs fix per comment from Lars.
[10 Feb 2009 17:08]
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/65776 3010 Luis Soares 2009-02-10 BUG#23300: Slow query log on slave does not log slow replicated statements When using replication, the slave will not log any slow query logs queries replicated from the master, even if the option "--slow-query-log" is set and these take more than "log_query_time" to execute. In order to log slow queries in replicated thread one needs to set the --log-slow-slave-statements, so that the SQL thread is initialized with the correct switch. Although setting this flag correctly configures the slave thread option to log slow queries, there is an issue with the condition that is used to check whether to log the slow query or not. When replaying binlog events the statement contains the SET TIMESTAMP clause which will force the slow logging condition check to fail. Consequently, the slow query logging does take place. This patch addresses this issue by removing the second condition from the log_slow_statements as it prevents slow queries to be binlogged and seems to be deprecated.
[12 Feb 2009 23:57]
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/66106 3010 Luis Soares 2009-02-13 BUG#23300: Slow query log on slave does not log slow replicated statements When using replication, the slave will not log any slow query logs queries replicated from the master, even if the option "--log-slow-slave-statements" is set and these take more than "log_query_time" to execute. In order to log slow queries in replicated thread one needs to set the --log-slow-slave-statements, so that the SQL thread is initialized with the correct switch. Although setting this flag correctly configures the slave thread option to log slow queries, there is an issue with the condition that is used to check whether to log the slow query or not. When replaying binlog events the statement contains the SET TIMESTAMP clause which will force the slow logging condition check to fail. Consequently, the slow query logging will not take place. This patch addresses this issue by removing the second condition from the log_slow_statements as it prevents slow queries to be binlogged and seems to be deprecated.
[19 Feb 2009 8:59]
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/66837 2817 Luis Soares 2009-02-19 BUG#23300: Slow query log on slave does not log slow replicated statements When using replication, the slave will not log any slow query logs queries replicated from the master, even if the option "--log-slow-slave-statements" is set and these take more than "log_query_time" to execute. In order to log slow queries in replicated thread one needs to set the --log-slow-slave-statements, so that the SQL thread is initialized with the correct switch. Although setting this flag correctly configures the slave thread option to log slow queries, there is an issue with the condition that is used to check whether to log the slow query or not. When replaying binlog events the statement contains the SET TIMESTAMP clause which will force the slow logging condition check to fail. Consequently, the slow query logging will not take place. This patch addresses this issue by removing the second condition from the log_slow_statements as it prevents slow queries to be binlogged and seems to be deprecated. added: mysql-test/suite/rpl/r/rpl_slow_query_log.result mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt mysql-test/suite/rpl/t/rpl_slow_query_log.test modified: sql/log.cc sql/sql_parse.cc
[19 Feb 2009 9:04]
Luis Soares
Pushed into 6.0-rpl tree.
[24 Mar 2009 17:20]
Bugs System
Pushed into 6.0.11-alpha (revid:alik@sun.com-20090324171507-s5aac9guj21l0jz6) (version source revid:luis.soares@sun.com-20090219085910-05i23vtboj9gj4fx) (merge vers: 6.0.10-alpha) (pib:6)
[25 Mar 2009 9:55]
Jon Stephens
Documented in the 6.0.11 changelog as follows:
Queries which were written to the slow query log on the master
were not written to the slow query log on the slave.
Also updated sections "The Slow Query Log" and "Replication and the Slow Query Log" in the 6.0 Manual.
Closed.
[28 May 2009 7:18]
Mats Kindahl
Note that BUG#45136, which is marked as a duplicate, is talking about that this option does not work while this bug report talks about it not being available in the options list. Both issues need to be fixed with this bug. For more information, see: BUG#45136, BUG#23300, and BUG#27492
[28 May 2009 7:20]
Mats Kindahl
Sorry, this comment was intended for BUG#45014.
[29 Sep 2009 12: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/84987 3113 Luis Soares 2009-09-29 BUG#23300: Slow query log on slave does not log slow replicated statements NOTE: this is the backport to next-mr. When using replication, the slave will not log any slow query logs queries replicated from the master, even if the option "--log-slow-slave-statements" is set and these take more than "log_query_time" to execute. In order to log slow queries in replicated thread one needs to set the --log-slow-slave-statements, so that the SQL thread is initialized with the correct switch. Although setting this flag correctly configures the slave thread option to log slow queries, there is an issue with the condition that is used to check whether to log the slow query or not. When replaying binlog events the statement contains the SET TIMESTAMP clause which will force the slow logging condition check to fail. Consequently, the slow query logging will not take place. This patch addresses this issue by removing the second condition from the log_slow_statements as it prevents slow queries to be binlogged and seems to be deprecated.
[29 Sep 2009 14:09]
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/85026 3114 Luis Soares 2009-09-29 BUG#23300: Slow query log on slave does not log slow replicated statements NOTE: this is the backport to next-mr. When using replication, the slave will not log any slow query logs queries replicated from the master, even if the option "--log-slow-slave-statements" is set and these take more than "log_query_time" to execute. In order to log slow queries in replicated thread one needs to set the --log-slow-slave-statements, so that the SQL thread is initialized with the correct switch. Although setting this flag correctly configures the slave thread option to log slow queries, there is an issue with the condition that is used to check whether to log the slow query or not. When replaying binlog events the statement contains the SET TIMESTAMP clause which will force the slow logging condition check to fail. Consequently, the slow query logging will not take place. This patch addresses this issue by removing the second condition from the log_slow_statements as it prevents slow queries to be binlogged and seems to be deprecated.
[27 Oct 2009 9:48]
Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091027094604-9p7kplu1vd2cvcju) (version source revid:zhenxing.he@sun.com-20091026140226-uhnqejkyqx1aeilc) (merge vers: 6.0.14-alpha) (pib:13)
[27 Oct 2009 18:16]
Jon Stephens
Already documented in 6.0.11 changelog; closed w/o further action.
[6 Nov 2009 10:03]
Andy Pritchard
I cant find any record of the fix for this bug or its many duplicates being moved into the 5.x releases. Since mysql 6 has been retired has this bug been overlooked.
[9 Nov 2009 9:39]
Andy Pritchard
Have raised Bug #48632 about this fix needing to be ported to the 5.x generation and the slow log documentation.
[9 Nov 2009 12:15]
Valeriy Kravchuk
Bug #48632 was marked as a duplicate of this one. We need fix for 5.x!
[9 Nov 2009 15:35]
Lars Thalmann
This bug is already pushed into the code for the next GA release coming after 5.1 (most likely 5.5 or 5.6). Whether this fix should go into 5.1 or not is handled in BUG#48632. Re-closing this bug.
[12 Nov 2009 8:17]
Bugs System
Pushed into 5.5.0-beta (revid:alik@sun.com-20091110093229-0bh5hix780cyeicl) (version source revid:alik@sun.com-20091027095744-rf45u3x3q5d1f5y0) (merge vers: 5.5.0-beta) (pib:13)
[12 Nov 2009 12:27]
Jon Stephens
Also documented bugfix in the 5.5.0 changelog; closed.
[23 Jan 2010 3:17]
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/97961 3333 Luis Soares 2010-01-23 BUG#48632: Fix for Bug #23300 Has Not Been Backported To 5.x Release Notes ===== This is a backport of BUG#23300 into 5.1 GA. Original cset revid: luis.soares@sun.com-20090219085910-05i23vtboj9gj4fx Description =========== When using replication, the slave will not log any slow query logs queries replicated from the master, even if the option "--log-slow-slave-statements" is set and these take more than "log_query_time" to execute. In order to log slow queries in replicated thread one needs to set the --log-slow-slave-statements, so that the SQL thread is initialized with the correct switch. Although setting this flag correctly configures the slave thread option to log slow queries, there is an issue with the condition that is used to check whether to log the slow query or not. When replaying binlog events the statement contains the SET TIMESTAMP clause which will force the slow logging condition check to fail. Consequently, the slow query logging will not take place. This patch addresses this issue by removing the second condition from the log_slow_statements as it prevents slow queries to be binlogged and seems to be deprecated.
[5 Feb 2010 17:01]
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/99494 3367 Luis Soares 2010-02-05 BUG#48632: Fix for Bug #23300 Has Not Been Backported To 5.x Release Notes ===== This is a backport of BUG#23300 into 5.1 GA. Original cset revid (in betony): luis.soares@sun.com-20090929140901-s4kjtl3iiyy4ls2h Description =========== When using replication, the slave will not log any slow query logs queries replicated from the master, even if the option "--log-slow-slave-statements" is set and these take more than "log_query_time" to execute. In order to log slow queries in replicated thread one needs to set the --log-slow-slave-statements, so that the SQL thread is initialized with the correct switch. Although setting this flag correctly configures the slave thread option to log slow queries, there is an issue with the condition that is used to check whether to log the slow query or not. When replaying binlog events the statement contains the SET TIMESTAMP clause which will force the slow logging condition check to fail. Consequently, the slow query logging will not take place. This patch addresses this issue by removing the second condition from the log_slow_statements as it prevents slow queries to be binlogged and seems to be deprecated.
[1 Mar 2010 8:44]
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:12]
Jon Stephens
Also documented in the 5.1.45 changelog. Closed.
[2 Mar 2010 14:33]
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:38]
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:43]
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 4:45]
Jon Stephens
Already documented in 5.5.0/6.0.11. Re-closing.
[9 Jun 2010 14:11]
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/110637 3103 Martin Skold 2010-06-09 [merge] Merged in 5.1.45 added: mysql-test/include/not_binlog_format_row.inc mysql-test/r/bug39022.result mysql-test/r/no_binlog.result mysql-test/r/partition_debug_sync.result mysql-test/std_data/bug48449.frm mysql-test/suite/rpl/r/rpl_slow_query_log.result mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt mysql-test/suite/rpl/t/rpl_slow_query_log.test mysql-test/t/bug39022.test mysql-test/t/no_binlog.test mysql-test/t/partition_debug_sync.test renamed: mysql-test/r/variables+c.result => mysql-test/r/variables_community.result mysql-test/t/variables+c.test => mysql-test/t/variables_community.test modified: client/mysql.cc client/mysql_upgrade.c client/mysqladmin.cc client/mysqlbinlog.cc client/mysqlcheck.c client/mysqldump.c client/mysqlimport.c client/mysqlshow.c client/mysqlslap.c client/mysqltest.cc cmd-line-utils/readline/rlmbutil.h cmd-line-utils/readline/text.c configure.in extra/yassl/include/yassl_error.hpp extra/yassl/src/ssl.cpp extra/yassl/src/yassl_error.cpp mysql-test/include/mtr_warnings.sql mysql-test/lib/My/ConfigFactory.pm mysql-test/lib/My/SafeProcess.pm mysql-test/lib/My/SafeProcess/safe_process_win.cc mysql-test/lib/mtr_cases.pm mysql-test/lib/mtr_gprof.pl mysql-test/lib/mtr_misc.pl mysql-test/lib/mtr_report.pm mysql-test/lib/mtr_stress.pl mysql-test/lib/v1/mtr_stress.pl mysql-test/lib/v1/mysql-test-run.pl mysql-test/mysql-test-run.pl mysql-test/r/archive.result mysql-test/r/backup.result mysql-test/r/bigint.result mysql-test/r/csv.result mysql-test/r/default.result mysql-test/r/delete.result mysql-test/r/fulltext.result mysql-test/r/func_gconcat.result mysql-test/r/func_time.result mysql-test/r/group_by.result mysql-test/r/group_min_max.result mysql-test/r/having.result mysql-test/r/innodb-autoinc.result mysql-test/r/innodb_mysql.result mysql-test/r/join.result mysql-test/r/log_state.result mysql-test/r/multi_update.result mysql-test/r/myisam.result mysql-test/r/mysqltest.result mysql-test/r/show_check.result mysql-test/r/sp-bugs.result mysql-test/r/sp-error.result mysql-test/r/sp.result mysql-test/r/sp_notembedded.result mysql-test/r/sp_trans.result mysql-test/r/subselect.result mysql-test/r/type_bit.result mysql-test/r/type_blob.result mysql-test/r/type_timestamp.result mysql-test/r/view.result mysql-test/r/view_grant.result mysql-test/r/warnings.result mysql-test/suite/rpl/r/rpl_sp.result mysql-test/suite/rpl/t/rpl_loaddata_symlink.test mysql-test/suite/sys_vars/r/log_basic.result mysql-test/suite/sys_vars/r/log_bin_trust_routine_creators_basic.result mysql-test/suite/sys_vars/r/slow_query_log_func.result mysql-test/suite/sys_vars/t/slow_query_log_func.test mysql-test/t/archive.test mysql-test/t/bigint.test mysql-test/t/csv.test mysql-test/t/delete.test mysql-test/t/fulltext.test mysql-test/t/func_gconcat.test mysql-test/t/group_by.test mysql-test/t/group_min_max.test mysql-test/t/having.test mysql-test/t/innodb-autoinc.test mysql-test/t/innodb_mysql.test mysql-test/t/join.test mysql-test/t/multi_update.test mysql-test/t/myisam.test mysql-test/t/mysqltest.test mysql-test/t/sp-bugs.test mysql-test/t/sp_notembedded.test mysql-test/t/subselect.test mysql-test/t/type_bit.test mysql-test/t/view.test mysql-test/t/view_grant.test mysys/default.c scripts/mysqld_multi.sh server-tools/instance-manager/options.cc sql/field.cc sql/ha_partition.cc sql/item.cc sql/item.h sql/item_cmpfunc.h sql/item_row.cc sql/item_sum.cc sql/item_timefunc.cc sql/log.cc sql/log_event.cc sql/log_event_old.cc sql/mysql_priv.h sql/mysqld.cc sql/opt_range.cc sql/opt_sum.cc sql/share/errmsg.txt sql/sp.cc sql/sp_cache.cc sql/sp_head.cc sql/sql_base.cc sql/sql_class.cc sql/sql_class.h sql/sql_lex.cc sql/sql_lex.h sql/sql_parse.cc sql/sql_repl.cc sql/sql_select.cc sql/sql_select.h sql/sql_table.cc sql/sql_trigger.cc sql/sql_update.cc sql/sql_view.cc sql/table.cc sql/table.h storage/archive/ha_archive.cc storage/csv/ha_tina.cc storage/innobase/buf/buf0buf.c storage/innobase/buf/buf0rea.c storage/innobase/handler/ha_innodb.cc storage/innobase/include/buf0rea.h storage/innobase/lock/lock0lock.c storage/innobase/os/os0file.c storage/myisam/ft_boolean_search.c storage/myisam/mi_dynrec.c storage/myisam/mi_locking.c support-files/mysql.spec.sh
[17 Jun 2010 12:04]
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:48]
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:31]
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: When using replication, the slave will not log any queries replicated from the master (see testcase). This behaviour _could_ be okay, if it were documented in the manual (see suggested fixes). Verified in 4.1, untested so far in 5.0, 5.1. How to repeat: CREATE TABLE index_test (id INT NOT NULL PRIMARY KEY auto_increment, a char(50), b char(50)) ENGINE=MyISAM; Insert some dummy rows: insert into index_test (a,b) values (REPEAT('a', 50), REPEAT('b', 50)); insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; insert into index_test (a,b) SELECT a,b FROM index_test; Add 50 partial indexes on a: ALTER TABLE index_test ADD INDEX idx_1 (a(1)), ADD INDEX idx_2 (a(2)), ADD INDEX idx_3 (a(3)), ADD INDEX idx_4 (a(4)), ADD INDEX idx_5 (a(5)), ADD INDEX idx_6 (a(6)), ADD INDEX idx_7 (a(7)), ADD INDEX idx_8 (a(8)), ADD INDEX idx_9 (a(9)), ADD INDEX idx_10 (a(10)), ADD INDEX idx_11 (a(11)), ADD INDEX idx_12 (a(12)), ADD INDEX idx_13 (a(13)), ADD INDEX idx_14 (a(14)), ADD INDEX idx_15 (a(15)), ADD INDEX idx_16 (a(16)), ADD INDEX idx_17 (a(17)), ADD INDEX idx_18 (a(18)), ADD INDEX idx_19 (a(19)), ADD INDEX idx_20 (a(20)), ADD INDEX idx_21 (a(21)), ADD INDEX idx_22 (a(22)), ADD INDEX idx_23 (a(23)), ADD INDEX idx_24 (a(24)), ADD INDEX idx_25 (a(25)), ADD INDEX idx_26 (a(26)), ADD INDEX idx_27 (a(27)), ADD INDEX idx_28 (a(28)), ADD INDEX idx_29 (a(29)), ADD INDEX idx_30 (a(30)), ADD INDEX idx_31 (a(31)), ADD INDEX idx_32 (a(32)), ADD INDEX idx_33 (a(33)), ADD INDEX idx_34 (a(34)), ADD INDEX idx_35 (a(35)), ADD INDEX idx_36 (a(36)), ADD INDEX idx_37 (a(37)), ADD INDEX idx_38 (a(38)), ADD INDEX idx_39 (a(39)), ADD INDEX idx_40 (a(40)), ADD INDEX idx_41 (a(41)), ADD INDEX idx_42 (a(42)), ADD INDEX idx_43 (a(43)), ADD INDEX idx_44 (a(44)), ADD INDEX idx_45 (a(45)), ADD INDEX idx_46 (a(46)), ADD INDEX idx_47 (a(47)), ADD INDEX idx_48 (a(48)), ADD INDEX idx_49 (a(49)), ADD INDEX idx_50 (a(50)); ** Attempt an update ** mysql> UPDATE index_test SET a=REPEAT('A', 50); This update would take at least 1 second on most systems. In my test it logs to the master's slow query log: # Query_time: 29 Lock_time: 0 Rows_sent: 0 Rows_examined: 0 use test2; UPDATE index_test SET a=REPEAT('B', 50); On the slave, the slow query log is empty: Tcp port: 3307 Unix socket: /tmp/mysql2.sock Time Id Command Argument Suggested fix: Either document in manual here <http://dev.mysql.com/doc/refman/5.0/en/slow-query-log.html>, or change behaviour (I vote change behaviour in next major release!)