Bug #49730 During Fast Index creation mysql client is locked

Description:
When InnoDB-plugin creates index on some time, mysql client
hangs on command
use DB;

where DB is database that contains the table where index is being created.

For example

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> show processlist;
+----+------+-----------+----------+------------+------+-------------------+--------------------------------------+
| Id | User | Host      | db       | Command    | Time | State             | Info                                 |
+----+------+-----------+----------+------------+------+-------------------+--------------------------------------+
|  1 | root | localhost | wikistat | Query      |   54 | manage keys       | alter table pages3 add key (crchash) |
|  7 | root | localhost | wikistat | Field List |   25 | Waiting for table |     

process 1 - is process with creating index.
process 7 is process:

mysql> use wikistat;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

So as you see process 7 hang in Command Field List State "Waiting for table"

How to repeat:
Create index in one thread
and
execute
use DB 
in another

Suggested fix:
Do not block mysql client

Thank you for the report.

I can not repeat described behavior with dummy data. Please provide output of SHOW CREATE TABLE pages3

Sveta,

Schema is

CREATE TABLE `pages3` (
  `id` int(10) unsigned NOT NULL,
  `page` varchar(2000) NOT NULL,
  `crchash` int(10) unsigned NOT NULL,
  PRIMARY KEY (`id`),
  KEY `crchash` (`crchash`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 KEY_BLOCK_SIZE=8

Parameters are:
innodb_buffer_pool_size=12G
innodb_log_file_size=256M
innodb_flush_log_at_trx_commit=2
innodb_flush_method=O_DIRECT

ignore-builtin-innodb
plugin-load=innodb=ha_innodb_plugin.so
plugin_dir=/data/vol1/engines/mysql-5.1.41/mysql-5.1.41-linux-x86_64-glibc23/lib/plugin
innodb_file_per_table=1
innodb_file_format=Barracuda

Thank you for the feedback.

I still can not repeat described behavior, although I can prove InnoDB Plugin locks LOCK_open while alters table and InnoDB does not.

Could you please attach gdb in locking time, then run `bt` and `bt full` commands and send us output, so we can see where it is locked?

Sveta,

Make sure you have big amount of data so ALTER TABLE ADD KEY runs long enough.

Here is bt for relevant threads

Thread 4 (Thread 0x49478940 (LWP 11198)):
#0  0x00000000008e106d in adler32 (adler=196091, 
    buf=0x2aac9b1d0d62 "%D1%82%D1%80%D0%BE%D0%BD%D0%BD%D0%B0%D1%8F_%D0%BF%D1%80%D0%BE%D0%BC%D1%8B%D1%88%D0%BB%D0%B5%D0%BD%D0%BD%D0%BE%D1%81%D1%82%D1%8C/[???,\2011\004:?M%D0%9A%D0%B0%D1%82%D0%B5%D0%B3%D0%BE%D1%80%D0%B8%D1%8F:%D0%AD"..., len=10798) at adler32.c:101
#1  0x00002aaaab2e1f61 in buf_zip_decompress (block=0x2aaab4525c40, check=<value optimized out>) at buf/buf0buf.c:1826
#2  0x00002aaaab2e56fe in buf_page_get_gen (space=6, zip_size=16384, offset=107754, rw_latch=1, guess=0x0, mode=10, 
    file=0x2aaaab3b5a0b "./include/btr0btr.ic", line=53, mtr=0x49474350) at buf/buf0buf.c:2234
#3  0x00002aaaab2d9fb7 in btr_pcur_move_to_next_page (cursor=0x494747f0, mtr=0x49474350) at ./include/btr0btr.ic:53
#4  0x00002aaaab378f83 in row_merge_read_clustered_index (trx=0x2f84f450, table=0x2f80df40, old_table=0x19ea4080, 
    new_table=0x19ea4080, index=0x2f890440, files=0x2f87e310, n_index=1, block=0x2aadcd708000) at ./include/btr0pcur.ic:350
#5  0x00002aaaab37a012 in row_merge_build_indexes (trx=0x2f84f450, old_table=0x19ea4080, new_table=0x19ea4080, indexes=0x2f7de120, 
    n_indexes=1, table=0x2f80df40) at row/row0merge.c:2480
#6  0x00002aaaab328bfc in ha_innodb::add_index (this=0x2f819d10, table=0x2f80df40, key_info=0x2f88f8c0, 
    num_of_keys=<value optimized out>) at handler/handler0alter.cc:798
#7  0x00000000006e9010 in mysql_alter_table (thd=0x2aadd006cf70, new_db=0x2f88e858 "wikistat", new_name=0x2f88e4f0 "pages0", 
    create_info=0x494770b0, table_list=0x2f88e528, alter_info=0x49477190, order_num=0, order=0x0, ignore=false)
---Type <return> to continue, or q <return> to quit---
    at sql_table.cc:7202
#8  0x00000000005f084a in mysql_execute_command (thd=0x2aadd006cf70) at sql_parse.cc:2898
#9  0x00000000005f59be in mysql_parse (thd=0x2aadd006cf70, inBuf=0x2f88e430 "alter table pages0 add key (crchash,id)", length=39, 
    found_semicolon=0x49478060) at sql_parse.cc:5970
#10 0x00000000005f68ae in dispatch_command (command=COM_QUERY, thd=0x2aadd006cf70, 
    packet=0x2aadd00c8751 "alter table pages0 add key (crchash,id)", packet_length=<value optimized out>) at sql_parse.cc:1231
#11 0x00000000005f7176 in do_command (thd=0x2aadd006cf70) at sql_parse.cc:872
#12 0x00000000005e9ad6 in handle_one_connection (arg=<value optimized out>) at sql_connect.cc:1127
#13 0x00000037e82064a7 in start_thread () from /lib64/libpthread.so.0
#14 0x00000037e7ad3c2d in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x494b9940 (LWP 11200)):
#0  0x00000037e820ab99 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x0000000000621606 in wait_for_condition (thd=0x2aadd00cc760, mutex=0xcdd760, cond=0xcddd60) at sql_base.cc:2169
#2  0x000000000062ad3a in open_table (thd=0x2aadd00cc760, table_list=0x494b8ac0, mem_root=0x494b8320, refresh=0x494b837f, flags=0)
    at sql_base.cc:2834
#3  0x000000000062bb29 in open_tables (thd=0x2aadd00cc760, start=0x494b83c8, counter=0x494b83dc, flags=0) at sql_base.cc:4581
#4  0x000000000062bc9e in open_normal_and_derived_tables (thd=0xcddd64, tables=0x494b8ac0, flags=4294967295) at sql_base.cc:5036
#5  0x00000000006fe182 in mysqld_list_fields (thd=0xcddd64, table_list=0x80, wild=0x2f7e04b8 "") at sql_show.cc:895
#6  0x00000000005f666a in dispatch_command (command=<value optimized out>, thd=0x2aadd00cc760, packet=0x2aadd00cf028 "", 
    packet_length=804458463) at sql_parse.cc:1340
#7  0x00000000005f7176 in do_command (thd=0x2aadd00cc760) at sql_parse.cc:872
#8  0x00000000005e9ad6 in handle_one_connection (arg=<value optimized out>) at sql_connect.cc:1127
#9  0x00000037e82064a7 in start_thread () from /lib64/libpthread.so.0
#10 0x00000037e7ad3c2d in clone () from /lib64/libc.so.6

( I have different table there, but the lock is the same)

Thank you for the report.

Verified as described.

To easily repeat modify sources as follow:

=== modified file 'sql/sql_table.cc'
--- sql/sql_table.cc    2009-11-27 13:34:39 +0000
+++ sql/sql_table.cc    2009-12-21 14:10:24 +0000
@@ -7297,6 +7297,7 @@
     my_free(new_table,MYF(0));
   }
   VOID(pthread_mutex_lock(&LOCK_open));
+  sleep(120);
   if (error)
   {
     VOID(quick_rm_table(new_db_type, new_db, tmp_name, FN_IS_TMP));

Then start server and run following queries:

create database db1;

use db1;
create table t1(f1 int unsigned not null auto_increment, f2 varchar(2000), f3  int(10) unsigned NOT NULL, PRIMARY KEY(f1)) engine=innodb ROW_FORMAT=COMPRESSED DEFAULT CHARSET=latin1 KEY_BLOCK_SIZE=8;
--disable_query_log
let $i=400;
while ($i)
{
--eval set @str=repeat(md5($i), 62);
--eval insert into t1(f2,f3) values(@str,$i);
--eval insert into t1(f2,f3) values(@str,$i);
--eval insert into t1(f2,f3) values(@str,$i);
dec $i;
}
--enable_query_log
select now();
alter table t1 add key(f3, f1);

(I use MTR to create data, but this should be not matter,

option file contains:

--innodb_flush_log_at_trx_commit=2 --innodb_flush_method=O_DIRECT --ignore-builtin-innodb --innodb_file_per_table=1 --innodb_file_format=Barracuda --ignore-builtin-innodb --plugin-load=innodb=ha_innodb_plugin.so --plugin-dir=/Users/apple/bzr/mysql-5.1/storage/innodb_plugin/.libs
)

Then in another terminal open new connection, run SHOW PROCESSLIST until you see row like:

|  3 | root | localhost | db1  | Query   |    1 | manage keys | alter table t2 add key(f3, f1) 

Then issue 

USE db1

In third terminal you can see SHOW PROCESSLIST output like in the initial reply:

mysql> show processlist;
+----+------+-----------+------+------------+------+----------------+--------------------------------+
| Id | User | Host      | db   | Command    | Time | State          | Info                           |
+----+------+-----------+------+------------+------+----------------+--------------------------------+
|  2 | root | localhost | db1  | Query      |   57 | manage keys    | alter table t1 add key(f3, f1) |
|  3 | root | localhost | db1  | Field List |   53 | Opening tables |                                |
|  4 | root | localhost | NULL | Query      |    0 | NULL           | show processlist               |
+----+------+-----------+------+------------+------+----------------+--------------------------------+
3 rows in set (0.00 sec)

to repeat:

thread 1:
---------
set old_alter_table=0;
drop table if exists t1;
create table t1(id int not null auto_increment primary key,a char(255) character set latin1)engine=innodb;
insert into t1(a) values ('a'),('b'),('c'),('d'),('e'),('f');
insert into t1(a) select t1.a from t1,t1 a,t1 b,t1 c,t1 d,t1 f,t1 g;
alter table t1 add index(a);

thread 2:
---------
select * from t1 limit 10;

thread 3:
---------
show processlist;

+---------+------+-------------------+-----------------------------+
| Command | Time | State             | Info                        |
+---------+------+-------------------+-----------------------------+
| Query   |    5 | manage keys       | alter table t1 add index(a) |
| Query   |    3 | Waiting for table | select * from t1 limit 10   |
| Query   |    0 | NULL              | show processlist            |
+---------+------+-------------------+-----------------------------+

stack traces in a readable format for the above test:

Stack Traces:

mysql> select * from t1 limit 10;

ntdll.dll!_ZwWaitForMultipleObjects@20
kernel32.dll!_WaitForMultipleObjectsEx@20
kernel32.dll!_WaitForMultipleObjects@16
mysqld.exe!pthread_cond_timedwait
mysqld.exe!pthread_cond_wait
mysqld.exe!wait_for_condition
mysqld.exe!open_table
mysqld.exe!open_tables
mysqld.exe!open_and_lock_tables_derived
mysqld.exe!execute_sqlcom_select
mysqld.exe!mysql_execute_command
mysqld.exe!mysql_parse
mysqld.exe!dispatch_command
mysqld.exe!do_command
mysqld.exe!handle_one_connection
mysqld.exe!pthread_start
mysqld.exe!_callthreadstart

mysql> alter table t1 add index(a);

ntdll.dll!_NtWriteFile
kernel32.dll!_WriteFile
ha_innodb_plugin.dll!os_file_write
ha_innodb_plugin.dll!row_merge_write
ha_innodb_plugin.dll!row_merge_write_rec
ha_innodb_plugin.dll!row_merge_blocks
ha_innodb_plugin.dll!row_merge
ha_innodb_plugin.dll!row_merge_sort
ha_innodb_plugin.dll!row_merge_build_indexes
ha_innodb_plugin.dll!ha_innodb::add_index
mysqld.exe!mysql_alter_table
mysqld.exe!mysql_execute_command
mysqld.exe!mysql_parse
mysqld.exe!dispatch_command
mysqld.exe!do_command
mysqld.exe!handle_one_connection
mysqld.exe!pthread_start
mysqld.exe!_callthreadstart

Is it repeatable in 5.5?
Values are low/low for 5.5.

Yes, this is repeatable with next-mr and mysql-trunk-bugfixing.

See also bug#42230

Setting the bug to patch pending as it is fixed by the patch submitted
(but not yet reviewed) for bug#42230.

Closing as a duplicate of Bug#42230