List:Commits« Previous MessageNext Message »
From:Staale Smedseng Date:May 12 2010 11:19am
Subject:bzr commit into mysql-5.1-bugteam branch (staale.smedseng:3380) Bug#49756
View as plain text  
#At file:///export/home/tmp/ss156133/z/49756-51/ based on revid:sven.sandberg@stripped

 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
=== 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 commit into mysql-5.1-bugteam branch (staale.smedseng:3380) Bug#49756Staale Smedseng12 May