3380 Staale Smedseng 2010-05-12
Bug #49756 Rows_examined is always 0 in the slow query log for
update statements
Only SELECT statements report any examined rows in the slow
log. Slow UPDATE, DELETE and INSERT statements report 0 rows
examined, unless the statement has a condition including a
SELECT substatement.
This patch adds counting of examined rows for the UPDATE and
DELETE statements. An INSERT ... VALUES statement will still
not report any rows as examined.
@ sql/sql_class.h
Added more docs for THD::examined_row_count.
@ sql/sql_delete.cc
Add incrementing thd->examined_row_count.
@ sql/sql_update.cc
Add incrementing thd->examined_row_count.
modified:
mysql-test/r/log_state.result
mysql-test/t/log_state.test
sql/sql_class.h
sql/sql_delete.cc
sql/sql_update.cc
3379 Sven Sandberg 2010-05-12
BUG#50410: rpl_ndb tests should run with binlog_format=row
Problem: The rpl_ndb did not set binlog_format explicitly. Since
the default is binlog_format=statement, it means that the suite
ran with that. ndb does not support binlog_format=statement,
and many tests were skipped because they sourced
include/have_binlog_format_row_or_mixed.inc
Fix: set binlog_format=row explicitly in the configuration file
for the rpl_ndb suite.
@ Makefile.am
Removed duplicate run of rpl_ndb suite with binlog_format=row.
Now that rpl_ndb is run with binlog_format=row by default, this
run that explicitly changes to binlog_format=row is not needed,
because it is covered by the following run.
@ mysql-test/suite/rpl_ndb/my.cnf
cluster only supports binlog_format=row.
@ mysql-test/suite/rpl_ndb/r/rpl_ndb_stm_innodb.result
updated result file
@ mysql-test/suite/rpl_ndb/t/rpl_ndb_stm_innodb.test
This test is supposed to use binlog_format=STATEMENT on
master. It uses innodb on master, so statement format is
supported.
modified:
Makefile.am
mysql-test/suite/rpl_ndb/my.cnf
mysql-test/suite/rpl_ndb/r/rpl_ndb_stm_innodb.result
mysql-test/suite/rpl_ndb/t/rpl_ndb_stm_innodb.test
=== modified file 'mysql-test/r/log_state.result'
--- a/mysql-test/r/log_state.result 2010-02-09 10:30:50 +0000
+++ b/mysql-test/r/log_state.result 2010-05-12 11:19:12 +0000
@@ -308,8 +308,41 @@ SET @@global.general_log = @old_general_
SET @@global.general_log_file = @old_general_log_file;
SET @@global.slow_query_log = @old_slow_query_log;
SET @@global.slow_query_log_file = @old_slow_query_log_file;
+#
+# Bug #49756 Rows_examined is always 0 in the slow query log
+# for update statements
+#
+SET @old_log_output = @@global.log_output;
+SET GLOBAL log_output = "TABLE";
+SET GLOBAL slow_query_log = ON;
+SET GLOBAL long_query_time = 0.001;
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE TABLE t2 (b INT, PRIMARY KEY (b));
+INSERT INTO t2 VALUES (3),(4);
+INSERT INTO t1 VALUES (1+sleep(.01)),(2);
+INSERT INTO t1 SELECT b+sleep(.01) from t2;
+UPDATE t1 SET a=a+sleep(.01) WHERE a>2;
+UPDATE t1 SET a=a+sleep(.01) ORDER BY a DESC;
+UPDATE t2 set b=b+sleep(.01) limit 1;
+UPDATE t1 SET a=a+sleep(.01) WHERE a in (SELECT b from t2);
+DELETE FROM t1 WHERE a=a+sleep(.01) ORDER BY a LIMIT 2;
+SELECT rows_examined,sql_text FROM mysql.slow_log;
+rows_examined sql_text
+0 INSERT INTO t1 VALUES (1+sleep(.01)),(2)
+2 INSERT INTO t1 SELECT b+sleep(.01) from t2
+4 UPDATE t1 SET a=a+sleep(.01) WHERE a>2
+8 UPDATE t1 SET a=a+sleep(.01) ORDER BY a DESC
+2 UPDATE t2 set b=b+sleep(.01) limit 1
+4 UPDATE t1 SET a=a+sleep(.01) WHERE a in (SELECT b from t2)
+6 DELETE FROM t1 WHERE a=a+sleep(.01) ORDER BY a LIMIT 2
+DROP TABLE t1,t2;
+TRUNCATE TABLE mysql.slow_log;
+# end of bug#49756
End of 5.1 tests
# Close connection con1
+SET GLOBAL long_query_time = DEFAULT;
+SET GLOBAL log_output = @old_log_output;
SET global general_log = @old_general_log;
SET global general_log_file = @old_general_log_file;
SET global slow_query_log = @old_slow_query_log;
=== modified file 'mysql-test/t/log_state.test'
--- a/mysql-test/t/log_state.test 2009-01-23 12:22:05 +0000
+++ b/mysql-test/t/log_state.test 2010-05-12 11:19:12 +0000
@@ -362,6 +362,42 @@ if(!$fixed_bug38124)
}
+###########################################################################
+
+--echo #
+--echo # Bug #49756 Rows_examined is always 0 in the slow query log
+--echo # for update statements
+--echo #
+
+SET @old_log_output = @@global.log_output;
+SET GLOBAL log_output = "TABLE";
+SET GLOBAL slow_query_log = ON;
+SET GLOBAL long_query_time = 0.001;
+
+# clear slow_log of any residual slow queries
+TRUNCATE TABLE mysql.slow_log;
+CREATE TABLE t1 (a INT);
+CREATE TABLE t2 (b INT, PRIMARY KEY (b));
+INSERT INTO t2 VALUES (3),(4);
+
+connect (con2,localhost,root,,);
+INSERT INTO t1 VALUES (1+sleep(.01)),(2);
+INSERT INTO t1 SELECT b+sleep(.01) from t2;
+UPDATE t1 SET a=a+sleep(.01) WHERE a>2;
+UPDATE t1 SET a=a+sleep(.01) ORDER BY a DESC;
+UPDATE t2 set b=b+sleep(.01) limit 1;
+UPDATE t1 SET a=a+sleep(.01) WHERE a in (SELECT b from t2);
+DELETE FROM t1 WHERE a=a+sleep(.01) ORDER BY a LIMIT 2;
+
+SELECT rows_examined,sql_text FROM mysql.slow_log;
+disconnect con2;
+connection default;
+DROP TABLE t1,t2;
+TRUNCATE TABLE mysql.slow_log;
+
+--echo # end of bug#49756
+
+
--echo End of 5.1 tests
--enable_ps_protocol
@@ -376,6 +412,8 @@ disconnect con1;
connection default;
# Reset global system variables to initial values if forgotten somewhere above.
+SET GLOBAL long_query_time = DEFAULT;
+SET GLOBAL log_output = @old_log_output;
SET global general_log = @old_general_log;
SET global general_log_file = @old_general_log_file;
SET global slow_query_log = @old_slow_query_log;
=== modified file 'sql/sql_class.h'
--- a/sql/sql_class.h 2010-04-14 09:53:59 +0000
+++ b/sql/sql_class.h 2010-05-12 11:19:12 +0000
@@ -1716,8 +1716,15 @@ public:
*/
ha_rows sent_row_count;
- /*
- number of rows we read, sent or not, including in create_sort_index()
+ /**
+ Number of rows read and/or evaluated for a statement. Used for
+ slow log reporting.
+
+ An examined row is defined as a row that is read and/or evaluated
+ according to a statement condition, including in
+ create_sort_index(). Rows may be counted more than once, e.g., a
+ statement including ORDER BY could possibly evaluate the row in
+ filesort() before reading it for e.g. update.
*/
ha_rows examined_row_count;
=== modified file 'sql/sql_delete.cc'
--- a/sql/sql_delete.cc 2010-02-26 12:58:33 +0000
+++ b/sql/sql_delete.cc 2010-05-12 11:19:12 +0000
@@ -248,6 +248,7 @@ bool mysql_delete(THD *thd, TABLE_LIST *
free_underlaid_joins(thd, &thd->lex->select_lex);
DBUG_RETURN(TRUE);
}
+ thd->examined_row_count+= examined_rows;
/*
Filesort has already found and selected the rows we want to delete,
so we don't need the where clause
@@ -304,6 +305,7 @@ bool mysql_delete(THD *thd, TABLE_LIST *
while (!(error=info.read_record(&info)) && !thd->killed &&
! thd->is_error())
{
+ thd->examined_row_count++;
// thd->is_error() is tested to disallow delete row on error
if (!(select && select->skip_record())&& ! thd->is_error() )
{
=== modified file 'sql/sql_update.cc'
--- a/sql/sql_update.cc 2010-05-11 14:39:51 +0000
+++ b/sql/sql_update.cc 2010-05-12 11:19:12 +0000
@@ -425,6 +425,7 @@ int mysql_update(THD *thd,
{
goto err;
}
+ thd->examined_row_count+= examined_rows;
/*
Filesort has already found and selected the rows we want to update,
so we don't need the where clause
@@ -471,6 +472,7 @@ int mysql_update(THD *thd,
while (!(error=info.read_record(&info)) && !thd->killed)
{
+ thd->examined_row_count++;
if (!(select && select->skip_record()))
{
if (table->file->was_semi_consistent_read())
@@ -577,6 +579,7 @@ int mysql_update(THD *thd,
while (!(error=info.read_record(&info)) && !thd->killed)
{
+ thd->examined_row_count++;
if (!(select && select->skip_record()))
{
if (table->file->was_semi_consistent_read())
Attachment: [text/bzr-bundle] bzr/staale.smedseng@sun.com-20100512111912-7hrbwfj0go76bdgy.bundle
| Thread |
|---|
| • bzr push into mysql-5.1-bugteam branch (staale.smedseng:3379 to 3380)Bug#49756 | Staale Smedseng | 12 May |
