MySQL Bugs: #31468: EXPLAIN executes data-modification statements when building plan

Bug #31468	EXPLAIN executes data-modification statements when building plan
Submitted:	8 Oct 2007 21:05	Modified:	8 Apr 2008 15:51
Reporter:	Philip Stoev	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Documentation	Severity:	S3 (Non-critical)
Version:	4.1+	OS:	Any
Assigned to:	Jon Stephens	CPU Architecture:	Any
Tags:	explain, side effects, subqueries

Description:
EXPLAIN is slow on the following query, which may mean that optimizer plan generation takes longer than usual.

How to repeat:
Run the following script:

use DBI;
my $dbh = DBI->connect('dbi:mysql:database=test');
$dbh->do("CREATE TABLE t1 (f1 INTEGER NOT NULL AUTO_INCREMENT, PRIMARY KEY (f1) );");

foreach my $i (1..100000) {
        $dbh->do("
                INSERT INTO t1 VALUES (NULL)
        ");
}

It creates a very simple table with 100000 rows. Then run:

mysql> explain SELECT * FROM t1 AS t1, (SELECT * FROM t1) AS t2;
+----+-------------+------------+-------+---------------+---------+---------+------+--------+-------------------+
| id | select_type | table      | type  | possible_keys | key     | key_len | ref  | rows   | Extra             |
+----+-------------+------------+-------+---------------+---------+---------+------+--------+-------------------+
|  1 | PRIMARY     | t1         | index | NULL          | PRIMARY | 4       | NULL | 100000 | Using index       |
|  1 | PRIMARY     | <derived2> | ALL   | NULL          | NULL    | NULL    | NULL | 100000 | Using join buffer |
|  2 | DERIVED     | t1         | index | NULL          | PRIMARY | 4       | NULL | 100000 | Using index       |
+----+-------------+------------+-------+---------------+---------+---------+------+--------+-------------------+
3 rows in set (0.39 sec)

Those 0.39 seconds are on a 1.4 Ghz Intel Core Duo inside Vmware.

Suggested fix:
It appears that the problem does not happen at 10000 rows. The problem does occur if two separate tables are referenced. The problem goes away if the subselect has a WHERE clause.

mysql> explain SELECT * FROM t1 AS t1, (SELECT * FROM t1 WHERE f1=5) AS t2;
+----+-------------+------------+--------+---------------+---------+---------+------+--------+-------------+
| id | select_type | table      | type   | possible_keys | key     | key_len | ref  | rows   | Extra       |
+----+-------------+------------+--------+---------------+---------+---------+------+--------+-------------+
|  1 | PRIMARY     | <derived2> | system | NULL          | NULL    | NULL    | NULL |      1 |             |
|  1 | PRIMARY     | t1         | index  | NULL          | PRIMARY | 4       | NULL | 100000 | Using index |
|  2 | DERIVED     | t1         | const  | PRIMARY       | PRIMARY | 4       |      |      1 | Using index |
+----+-------------+------------+--------+---------------+---------+---------+------+--------+-------------+
3 rows in set (0.00 sec)

The behavoir occurs with the latest 5.2 BK tree. If we go one level deeper:

mysql> explain SELECT 1 FROM t1 AS t1, (SELECT 1 FROM t2, (SELECT 1 FROM t1) AS t3) AS t2;
ERROR 126 (HY000): Incorrect key file for table '/tmp/#sql_6148_1.MYI'; try to repair it

after about a minute of 100% cpu usage; SHOW PROCESSLIST shows "sending data"; system runs out of disk space

mysql> explain SELECT * FROM t1 AS t1, (SELECT BENCHMARK(1223444, MD5(NOW())) ) AS t2;
+----+-------------+------------+--------+---------------+---------+---------+------+--------+----------------+
| id | select_type | table      | type   | possible_keys | key     | key_len | ref  | rows   | Extra          |
+----+-------------+------------+--------+---------------+---------+---------+------+--------+----------------+
|  1 | PRIMARY     | <derived2> | system | NULL          | NULL    | NULL    | NULL |      1 |                |
|  1 | PRIMARY     | t1         | index  | NULL          | PRIMARY | 4       | NULL | 100000 | Using index    |
|  2 | DERIVED     | NULL       | NULL   | NULL          | NULL    | NULL    | NULL |   NULL | No tables used |
+----+-------------+------------+--------+---------------+---------+---------+------+--------+----------------+
3 rows in set (5.69 sec)

It appears that BENCHMARK() is actually executed during the EXPLAIN. If this was a data-modifying stored procedure, the user may be surprised to find that EXPLAIN had a data-manipulation side-effect.

An example with a stored function that performs an INSERT:

mysql> CREATE TABLE `log` (
  `f1` int(11) NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`f1`)
mysql> delimiter //
mysql> CREATE FUNCTION simpleproc () RETURNS integer BEGIN INSERT INTO log VALUES(); RETURN 1; END;//
mysql> explain SELECT * FROM t1 AS t1, (SELECT simpleproc() ) AS t2;
+----+-------------+------------+--------+---------------+---------+---------+------+--------+----------------+
| id | select_type | table      | type   | possible_keys | key     | key_len | ref  | rows   | Extra          |
+----+-------------+------------+--------+---------------+---------+---------+------+--------+----------------+
|  1 | PRIMARY     | <derived2> | system | NULL          | NULL    | NULL    | NULL |      1 |                |
|  1 | PRIMARY     | t1         | index  | NULL          | PRIMARY | 4       | NULL | 100000 | Using index    |
|  2 | DERIVED     | NULL       | NULL   | NULL          | NULL    | NULL    | NULL |   NULL | No tables used |
+----+-------------+------------+--------+---------------+---------+---------+------+--------+----------------+
3 rows in set (0.00 sec)

mysql> select * from log;
+----+
| f1 |
+----+
| 12 |
+----+
1 row in set (0.01 sec)

Here is the backtrace for "explain SELECT * FROM t1 AS t1, (SELECT CURTIME() ) AS t2". mysql_handle_derived() calls mysql_derived_filling() even though this is just an EXPLAIN.

#0  Item_func_curtime::val_str (this=0xa340108, str=0xbf9430ac) at item_timefunc.cc:1547
#1  0x081dd01a in Item::get_time (this=0xa340108, ltime=0xbf9430f4) at item.cc:940
#2  0x081d857b in Item::save_time_in_field (this=0xa340108, field=0xa343228) at item.cc:320
#3  0x082351d4 in Item_str_timefunc::save_in_field (this=0xa340108, field=0xa343228, no_conversions=false) at item_timefunc.h:430
#4  0x082dcfb8 in fill_record (thd=0xa3095e8, ptr=0xa34309c, values=@0xa33fd8c, ignore_errors=true) at sql_base.cc:6996
#5  0x084264d8 in select_union::send_data (this=0xa3406a0, values=@0xa33fd8c) at sql_union.cc:60
#6  0x0832749d in JOIN::exec (this=0xa33d710) at sql_select.cc:2190
#7  0x08324537 in mysql_select (thd=0xa3095e8, rref_pointer_array=0xa33fdfc, tables=0x0, wild_num=0, fields=@0xa33fd8c, conds=0x0, og_num=0, order=0x0,
    group=0x0, having=0x0, proc_param=0x0, select_options=2416200192, result=0xa3406a0, unit=0xa33fe88, select_lex=0xa33fcf8) at sql_select.cc:2886
#8  0x084269f0 in mysql_derived_filling (thd=0xa3095e8, lex=0xa30a3ec, orig_table_list=0xa340450) at sql_derived.cc:263
#9  0x0842679b in mysql_handle_derived (lex=0xa30a3ec, processor=0x8426820 <mysql_derived_filling(THD*, st_lex*, TABLE_LIST*)>) at 
#10 0x082ec439 in open_and_lock_tables (thd=0xa3095e8, tables=0xa33f8c8) at sql_base.cc:3910
#11 0x082a16b7 in execute_sqlcom_select (thd=0xa3095e8, all_tables=0xa33f8c8) at sql_parse.cc:4428
#12 0x082a2f40 in mysql_execute_command (thd=0xa3095e8) at sql_parse.cc:1787
#13 0x082ab6dd in mysql_parse (thd=0xa3095e8, inBuf=0xa33f738 "explain SELECT * FROM t1 AS t1, (SELECT CURTIME() ) AS t2", length=57,
    found_semicolon=0xbf9447a4) at sql_parse.cc:5375
#14 0x082ac072 in dispatch_command (command=COM_QUERY, thd=0xa3095e8, packet=0xa33b6d9 "explain SELECT * FROM t1 AS t1, (SELECT CURTIME() ) AS t2",
    packet_length=58) at sql_parse.cc:859
#15 0x082ad223 in do_command (thd=0xa3095e8) at sql_parse.cc:649
#16 0x0829b761 in handle_one_connection (arg=0xa3095e8) at sql_connect.cc:1111
#17 0x0828fa3f in handle_connection_in_main_thread (thd=0xa3095e8) at mysqld.cc:4284
#18 0x082935d9 in create_new_thread (thd=0xa3095e8) at mysqld.cc:4384
#19 0x08293b3d in handle_connections_sockets (arg=0x0) at mysqld.cc:4609
#20 0x08296705 in main (argc=3, argv=0xbf944be4) at mysqld.cc:3969

This is expected and documented behaviour. Please, read the manual, http://dev.mysql.com/doc/refman/5.1/en/unnamed-views.html:

"Subqueries in the FROM clause are executed even for the EXPLAIN statement (that is, derived temporary tables are built). This occurs because upper-level queries need information about all tables during the optimization phase, and the table represented by a subquery in the FROM clause is unavailable unless the subquery is executed."

Yes, I understand that EXPLAIN will be very slow for those types of queries. However the issue is that data modification statements are also executed, which, in my humble opinion, is a bug. We should at least document that explicitly.

I have changed the title of the bug accordingly.

You can never be sure how many times function will be executed in SQL statement. So, if it modifies data each time (and, thus, is NOT deterministic), you are always in trouble.

Anyway, I do agree that explicit warning in documentation is needed. I'd also expect optimizer to NOT allow functions in cases like that if they do NOT have DETERMINISTIC property. And if function is created as DETERMINISTIC, it should NOT contain any INSERT/UPDATE/DELETE statements. These will prevent the problem to some extent.

Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly, and will be included in the next release of the relevant products.

See bug #44802