MySQL Bugs: #31700: thd->examined_row_count not incremented for 'const' type queries

Bug #31700	thd->examined_row_count not incremented for 'const' type queries
Submitted:	18 Oct 2007 19:44	Modified:	26 Nov 2007 18:50
Reporter:	Maciej Dobrzanski	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.0, 5.1, 4.1, 5.2 bk	OS:	Any
Assigned to:	Tatiana Azundris Nuernberg	CPU Architecture:	Any
Tags:	slow log

Description:
Examined rows counter is not incremented if data is selected by primary key or unique key. The effect can be seen in slow log.

How to repeat:
Incorrect behaviour:

mysql> explain select sql_no_cache * from t1 where ssid = 1 and nv = 4;        
+----+-------------+-------+-------+---------------+--------+---------+-------------+------+-------+
| id | select_type | table | type  | possible_keys | key    | key_len | ref         | rows | Extra |
+----+-------------+-------+-------+---------------+--------+---------+-------------+------+-------+
|  1 | SIMPLE      | t1    | const | ssid_2,nv     | ssid_2 | 5       | const,const |    1 |       | 
+----+-------------+-------+-------+---------------+--------+---------+-------------+------+-------+
1 row in set (0.01 sec)

mysql> select sql_no_cache * from t1 where ssid = 1 and nv = 4;        
+----+----------------------------------+------+----+
| id | token                            | ssid | nv |
+----+----------------------------------+------+----+
|  4 | 8c201c615b8843809cc028db78ddd7c0 |    1 |  4 | 
+----+----------------------------------+------+----+
1 row in set (0.00 sec)

# Time: 071018 21:33:35
# User@Host: macko[macko] @ localhost []
# Query_time: 0.000756  Lock_time: 0.000245 Rows_sent: 1  Rows_examined: 0
SET timestamp=1192736015;
select sql_no_cache * from t1 where ssid = 1 and nv = 4;

Works correctly with non-unique indexes:

mysql> explain select sql_no_cache * from t1 where nv = 4;             
+----+-------------+-------+------+---------------+------+---------+-------+------+-------+
| id | select_type | table | type | possible_keys | key  | key_len | ref   | rows | Extra |
+----+-------------+-------+------+---------------+------+---------+-------+------+-------+
|  1 | SIMPLE      | t1    | ref  | nv            | nv   | 1       | const |    1 |       | 
+----+-------------+-------+------+---------------+------+---------+-------+------+-------+
1 row in set (0.00 sec)

mysql> select sql_no_cache * from t1 where nv = 4;             
+----+----------------------------------+------+----+
| id | token                            | ssid | nv |
+----+----------------------------------+------+----+
|  4 | 8c201c615b8843809cc028db78ddd7c0 |    1 |  4 | 
+----+----------------------------------+------+----+
1 row in set (0.00 sec)

# Time: 071018 21:33:43
# User@Host: macko[macko] @ localhost []
# Query_time: 0.000856  Lock_time: 0.000229 Rows_sent: 1  Rows_examined: 1
SET timestamp=1192736023;
select sql_no_cache * from t1 where nv = 4;

Thank you for the report.

Verified as described.

notes

Let there be three columns, unique, non-unique, and non-indexed:

create table t1 (f1 serial,f2 int, f3 int, primary key(f1), key(f2));
insert into t1 values (1,1,1);
insert into t1 values (2,2,2);
insert into t1 values (3,3,3);
insert into t1 values (4,4,4);

Non-indexed:
select sql_no_cache * from t1 where f3=4;
Goes through evaluate_join_record()
Query_time: 00  Lock_time: 0  Rows_sent: 1  Rows_examined: 4

Same for empty set (f3=99):
Query_time: 00  Lock_time: 0  Rows_sent: 0  Rows_examined: 4

Indexed:
select sql_no_cache * from t1 where f2=3;
Goes through do_select() -> sub_select() -> evaluate_join_record()
Query_time: 99  Lock_time: 0  Rows_sent: 1  Rows_examined: 1

Empty set (f2=99):
Goes through same code-path, but evaluate_join_record() bails right away
(being out of rows and all), and thus doesn't count up join->examined_rows:
Query_time: 99  Lock_time: 0  Rows_sent: 0  Rows_examined: 0

Primary key:
select sql_no_cache * from t1 where f1=1;
Query_time: 99  Lock_time: 0  Rows_sent: 1  Rows_examined: 0/1
Code-path: do_select() -> end_send()

Now, empty set via PK:
Query_time: 99  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
Here we get a zero_result_cause in JOIN::exec() before we ever get to do_select().  (Leaving this note in case we some day decide we want to count key lookups too, but since we don't count up on missed non-UNIQUE keys, not doing it for UNIQUE here should count as intended behaviour.)

IOW, we only count actual rows we read, not key lookups. (We still count the row as read if the index was enough to satisfy the query however. Also, we do not see rows_examined when UPDATEing (non-indexed, 5.0).)

#0  end_send (join=0x8d97538, join_tab=0x8d98c58, end_of_records=false) at sql_select.cc:11404
#1  0x08291540 in do_select (join=0x8d97538, fields=0x8d60398, table=0x0, procedure=0x0) at sql_select.cc:10339
#2  0x082a78ba in JOIN::exec (this=0x8d97538) at sql_select.cc:2101
#3  0x082a37f3 in mysql_select (thd=0x8d5f360, rref_pointer_array=0x8d60428, tables=0x8d97130, wild_num=1, fields=@0x8d60398, conds=0x8d973d8, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2156153344, result=0x8d97528, unit=0x8d600cc, select_lex=0x8d60304) at sql_select.cc:2279
#4  0x082a7bce in handle_select (thd=0x8d5f360, lex=0x8d60074, result=0x8d97528, setup_tables_done_option=0) at sql_select.cc:256
#5  0x0823c368 in mysql_execute_command (thd=0x8d5f360) at sql_parse.cc:2675
#6  0x082446dc in mysql_parse (thd=0x8d5f360, inBuf=0x8d97000 "select sql_no_cache * from t1 where f1=1") at sql_parse.cc:6097

Const failing in end_send() because HAVING is not satisfied:
select sql_no_cache * from t1 where f1=3 having f3=3;

non-UNIQUE, having satisfied:
select sql_no_cache * from t1 where f2=3 having f3=4;
Query_time: 99  Lock_time: 0  Rows_sent: 1  Rows_examined: 1

non-UNIQUE, having not satisfied:
select sql_no_cache * from t1 where f2=3 having f3=99;
Query_time: 99  Lock_time: 0  Rows_sent: 0  Rows_examined: 1

Conclusion: we need to count const hits, but not const misses. Const hits count whether or not HAVING is satisfied (so, rather unsurprisingly, we can't just use send_records).

Corollary:
Put either in do_select()

    if (!join->conds || join->conds->val_int())
    {
      error= (*end_select)(join,join_tab,0);
      if (error == NESTED_LOOP_OK || error == NESTED_LOOP_QUERY_LIMIT)
+     {
+       join->examined_rows++;
        error= (*end_select)(join,join_tab,1);
+     }
    }

or into the end_*()s (arguably more correct, e.g. w/r/t cursors).

Now for Halloween ...

slow-query-log uses:
thd->sent_row_count (++'d in select_send::send_data; or set from thd->row_count in select_export)
thd->examined_row_count (fed from join->examined_rows, which is the rows we read, even if we discard them later (HAVING, LIMIT, ...))

select_to_file, select_export, select_dump, select_dumpvar use:
thd->row_count

EXPLAIN uses:
join->best_positions[i].records_read (0..i..join_tables)

FOUND_ROWS() uses:
thd->limit_found_rows
Meaning depends on SQL_CALC_FOUND_ROWS; if it was present in previous SELECT, limit_found_rows is the size the result set would have been had there not been a LIMIT clause (which makes it equal to the size of the result set if LIMIT is not used), or the size of the result-set otherwise.
limit_found_rows is fed from (join->) send_records. (s/b sent_records.) Note that a records may be synthetic (ROLLUP) and may not have a corresponding row!

Client uses MYSQL_RES.row_count (which usually is MYSQL_RES.MYSQL_DATA.rows)

subtle difference:
create_sort_index() counts up join->examined_rows, but not thd->row_count (both are counted up in evaluate_join_record() => so we should also count up both for const)

# Query_time: 6  Lock_time: 0  Rows_sent: 2  Rows_examined: 10
select sql_no_cache f1,sum(f2) as keks from t1 group by f3 having keks>2;

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/37519

ChangeSet@1.2557, 2007-11-10 18:29:13+01:00, tnurnberg@mysql.com +2 -0
  Bug#31700: thd->examined_row_count not incremented for 'const' type queries
  
  UNIQUE (eq-ref) lookups result in table being considered as a "constant" table.
  Queries that consist of only constant tables are processed in do_select() in a
  special way that doesn't invoke evaluate_join_record(), and therefore doesn't
  increase the counters join->examined_rows and join->thd->row_count.
  
  The patch increases these counters in this special case.
  
  NOTICE:
  This behavior seems to contradict what the documentation says in Sect. 5.11.4:
  "Queries handled by the query cache are not added to the slow query log, nor
  are queries that would not benefit from the presence of an index because the
  table has zero rows or one row."
  
  No test case in 5.0 as issue shows only in slow query log, and other counters
  can give subtly different values (with regard to counting in create_sort_index(),
  synthetic rows in ROLLUP, etc.).

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/37528

ChangeSet@1.2616, 2007-11-10 21:51:47+01:00, tnurnberg@mysql.com +2 -0
  Bug#31700: thd->examined_row_count not incremented for 'const' type queries
  
  add 5.1-specific test showing that 'const' access increments 'examined'
  counter in slow query log.

pushed to 5.0.52, 5.1.23 in opt

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/37840

ChangeSet@1.2641, 2007-11-15 12:30:35+01:00, tnurnberg@mysql.com +2 -0
  Bug#31700: thd->examined_row_count not incremented for 'const' type queries
  
  tests adjusted for Windows

Pushed into 5.0.52

Pushed into 5.1.23-rc

Pushed into 6.0.4-alpha

Noted in 5.0.52, 5.1.23, 6.0.4 changelogs.

The examined-rows count was not incremented for const queries.