Bug #49756 Rows_examined is always 0 in the slow query log for update statements

• Submitted: 17 Dec 2009 4:39
• Modified: 14 Oct 2010 13:56
• Reporter: Mark Callaghan
• Status: Closed
• Category: MySQL Server: Logging
• Severity: S3 (Non-critical)
• Version: 5.0.44, 5.1.43
• OS: Any
• Assigned to: Staale Smedseng
• CPU Architecture: Any
• Tags: log, query, Rows_examined, slow, UPDATE

[17 Dec 2009 4:39] Mark Callaghan

Description:
Rows_examined appears to always be 0 for UPDATE statements. I assume it is also always 0 for INSERT and DELETE as the only code that increments examined_row_count is in sql_select.cc and sql_union.cc.

How to repeat:
Read the code -- search for examined_row_count.
Run an update statement and check the slow query log.

Suggested fix:
Strive for feature completeness. Why was this implemented to only count rows for SELECT statements?

[17 Dec 2009 5:06] Valeriy Kravchuk

Verified with recent 5.1.43 from bzr:

77-52-7-73:5.1 openxs$ tail var/*slow.log
==> var/77-52-245-21-slow.log <==
# User@Host: root[root] @ localhost []
# Query_time: 383.982981  Lock_time: 0.000260 Rows_sent: 32  Rows_examined: 32
use test;
SET timestamp=1261025784;
select i, sleep(12) from t1;
# Time: 091217  7:03:06
# User@Host: root[root] @ localhost []
# Query_time: 96.000414  Lock_time: 0.000247 Rows_sent: 0  Rows_examined: 0
SET timestamp=1261026186;
update t1 set j = sleep(3);

I'd say this is actually a bug (incomplete feature implementation).

[29 Apr 2010 15:33] Davi Arnaut

FWIW, it is due to how conditions are evaluated in the update/delete execution paths -- and, actually, a detail. Examined_row_count is updated when there are joins in the query -- including for update and delete, although it will be inaccurate. For example, in case of a update, the examined row count can be calculated with row_count + examined_row_count.

[29 Apr 2010 15:41] Davi Arnaut

row_count above means THD::row_count. Finding out what the various count variables means is a mysterious and adventurous journey!

[4 May 2010 15:33] 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/107368

3449 Staale Smedseng	2010-05-04
      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 examined row is defined as a row that is
      read and/or evaluated according to a statement condition. A
      statement including ORDER BY will possibly execute filesort(),
      evaluating the same rows more than once. An INSERT ... VALUES
      will still not report any rows as examined.
     @ sql/sql_delete.cc
        Add incrementing thd->examined_row_count.
     @ sql/sql_update.cc
        Add incrementing thd->examined_row_count. It is incremented
        separately in the final while-loop as thd->row_count (which
        essentially counts the same rows) is possibly off by one (it
        is either initialized to 1 or reset to 0 depending on
        code-path chosen).

[7 May 2010 9:05] 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/107715

3449 Staale Smedseng	2010-05-07
      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.

[12 May 2010 11:19] 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/108110

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.

[28 May 2010 6:09] Bugs System

Pushed into mysql-next-mr (revid:[e-mail]-20100524190136-egaq7e8zgkwb9aqi) (version source revid:[e-mail]-20100524190136-egaq7e8zgkwb9aqi) (pib:16)

[28 May 2010 6:38] Bugs System

Pushed into 6.0.14-alpha (revid:[e-mail]-20100524190941-nuudpx60if25wsvx) (version source revid:[e-mail]-20100514054548-91z72f0mcskr84kj) (merge vers: 6.0.14-alpha) (pib:16)

[28 May 2010 7:06] Bugs System

Pushed into 5.5.5-m3 (revid:[e-mail]-20100524185725-c8k5q7v60i5nix3t) (version source revid:[e-mail]-20100523204118-0tl3goawu658rxh6) (merge vers: 5.5.5-m3) (pib:16)

[2 Jun 2010 8:49] Bugs System

Pushed into 5.1.48 (revid:[e-mail]-20100602084411-2yu607bslbmgufl3) (version source revid:[e-mail]-20100512111912-7hrbwfj0go76bdgy) (merge vers: 5.1.47) (pib:16)

[8 Jun 2010 18:59] Paul DuBois

Noted in 5.1.48, 5.5.5, 6.0.14 changelogs.

The Rows_examined value in slow query log rows now is nonzero for
UPDATE and DELETE statements that modify rows.

[14 Oct 2010 8:39] Bugs System

Pushed into mysql-5.1-telco-7.0 5.1.51-ndb-7.0.20 (revid:[e-mail]-20101014082627-jrmy9xbfbtrebw3c) (version source revid:[e-mail]-20100513074652-0cvlhgkesgbb2bfh) (merge vers: 5.5.5-m3) (pib:21)

[14 Oct 2010 8:54] Bugs System

Pushed into mysql-5.1-telco-6.3 5.1.51-ndb-6.3.39 (revid:[e-mail]-20101014083757-5qo48b86d69zjvzj) (version source revid:[e-mail]-20100513074652-0cvlhgkesgbb2bfh) (merge vers: 5.5.5-m3) (pib:21)

[14 Oct 2010 9:11] Bugs System

Pushed into mysql-5.1-telco-6.2 5.1.51-ndb-6.2.19 (revid:[e-mail]-20101014084420-y54ecj85j5we27oa) (version source revid:[e-mail]-20100513074652-0cvlhgkesgbb2bfh) (merge vers: 5.5.5-m3) (pib:21)

[14 Oct 2010 13:56] Jon Stephens

Already documented in the 5.1.48 changelog; no additional changelog entries required. Set back to Closed state.