Bug #12240 Rows Examined in Slow Log showing incorrect number?
Submitted: 28 Jul 2005 14:04 Modified: 20 Oct 2006 17:46
Reporter: Tobias Asplund Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:4.1.13 OS:Windows (Windows\Linux)
Assigned to: Ingo Strüwing CPU Architecture:Any

[28 Jul 2005 14:04] Tobias Asplund
Description:
Doesn't seem like the slow log actually picks up the right number of examined rows when putting an entry into it.

I'd expect the number to be either the sum or the product of the involved tables, depending on how it's getting counted with the block nested loop here (assuming that's what's used).

How to repeat:
mysql> SELECT COUNT(*) FROM Country;
+----------+
| COUNT(*) |
+----------+
|      239 |
+----------+
1 row in set (0.00 sec)

mysql> SELECT COUNT(*) FROM CountryLanguage;
+----------+
| COUNT(*) |
+----------+
|      984 |
+----------+
1 row in set (0.00 sec)

mysql> SELECT COUNT(*) FROM City;
+----------+
| COUNT(*) |
+----------+
|     4078 |
+----------+
1 row in set (0.01 sec)

mysql> SELECT COUNT(*) FROM City, Country, CountryLanguage;
+-----------+
| COUNT(*)  |
+-----------+
| 959047728 |
+-----------+
1 row in set (47.07 sec)

Produces the following entry in the slow log:

# Time: 050728 15:00:17
# User@Host: root[root] @ localhost [127.0.0.1]
# Query_time: 47  Lock_time: 0  Rows_sent: 1  Rows_examined: 4078
SELECT COUNT(*) FROM City, Country, CountryLanguage;
[28 Aug 2006 13:58] Tobias Asplund
Another example that produces the wrong output:

SELECT Name FROM Country WHERE Code IN (SELECT CountryCode FROM City WHERE Population > 8000000);

Using the world database from the manual pages.

# Time: 060718 18:01:05
# User@Host: flupps[flupps] @ localhost []
# Query_time: 4  Lock_time: 0 Rows_sent: 10  Rows_examined: 239
SET timestamp=1153238465;
SELECT Name FROM Country WHERE Code IN (SELECT CountryCode FROM City WHERE Population > 8000000);

explain for this shows:
+----+--------------------+---------+------+---------------+------+---------+------+------+-------------+
| id | select_type        | table   | type | possible_keys | key  | key_len | ref  | rows | Extra       |
+----+--------------------+---------+------+---------------+------+---------+------+------+-------------+
|  1 | PRIMARY            | Country | ALL  | NULL          | NULL | NULL    | NULL |  239 | Using where | 
|  2 | DEPENDENT SUBQUERY | City    | ALL  | NULL          | NULL | NULL    | NULL | 4079 | Using where | 
+----+--------------------+---------+------+---------------+------+---------+------+------+-------------+

So I assume that 239 + (239 * 4079) would be the number of examined here.
[10 Oct 2006 13:48] Ingo Strüwing
The world database examples do not log any command in the slow log for me (4.1.22). The other file does not seem to exist anymore.

If you want this bug fixed, please come up with needed server options / system variable settings and whatever is necessary to repeat it.
[10 Oct 2006 14:10] Tobias Asplund
--log-slow-queries --log-queries-not-using-indexes --long-query-time=1

should probably be able to do it
[10 Oct 2006 16:15] Ingo Strüwing
OK. This brought the last example statement into the slow query log at least. In 4.1 and 5.0, but not in 5.1(?).
[11 Oct 2006 7:53] 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/13448

ChangeSet@1.2560, 2006-10-11 09:52:53+02:00, istruewing@chilla.local +1 -0
  Bug#12240 - Rows Examined in Slow Log showing incorrect number?
  
  Examined rows are counted for every join part. The per-join-part
  counter was incremented over all iterations. The result variable
  was replaced at the end of every iteration. The final result was
  the number of examined rows by the join part that ended its
  execution as the last one. The numbers of other join parts was
  lost.
  
  Now we reset the per-join-part counter before every iteration and
  add it to the result variable at the end of the iteration. That
  way we get the sum of all iterations of all join parts.
[11 Oct 2006 10:25] 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/13469

ChangeSet@1.2560, 2006-10-11 12:24:59+02:00, istruewing@chilla.local +1 -0
  Bug#12240 - Rows Examined in Slow Log showing incorrect number?
  
  Examined rows are counted for every join part. The per-join-part
  counter was incremented over all iterations. The result variable
  was replaced at the end of every iteration. The final result was
  the number of examined rows by the join part that ended its
  execution as the last one. The numbers of other join parts was
  lost.
  
  Now we reset the per-join-part counter before every iteration and
  add it to the result variable at the end of the iteration. That
  way we get the sum of all iterations of all join parts.
  
  No test case. Testing this needs a look into the slow query log.
  I don't know of a way to do this portably with the test suite.
[16 Oct 2006 7:33] Ingo Strüwing
Reviewed by Sergey Vojtovich and Calvin Sun.
[17 Oct 2006 13:44] Ingo Strüwing
Pushed to 5.1-engines, 5.0-engines, and 4.1-engines.
[20 Oct 2006 9:10] Ingo Strüwing
Pushed to 5.1.13, 5.0.27, and 4.1.22.
[20 Oct 2006 17:46] Paul DuBois
Noted in 4.1.22, 5.0.27, 5.1.13 changelogs.

Entries in the slow query log could have an incorrect Rows_examined
value.
[25 Oct 2006 16:39] Paul DuBois
The 5.0.x fix is in 5.0.30.