MySQL Bugs: #12240: Rows Examined in Slow Log showing incorrect number?

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

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;

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.

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.

--log-slow-queries --log-queries-not-using-indexes --long-query-time=1

should probably be able to do it

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(?).

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.

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.

Reviewed by Sergey Vojtovich and Calvin Sun.

Pushed to 5.1-engines, 5.0-engines, and 4.1-engines.

Pushed to 5.1.13, 5.0.27, and 4.1.22.

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.

The 5.0.x fix is in 5.0.30.