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: | |
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
[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.