Bug #67124 CREATE INDEX is slow
Submitted: 7 Oct 2012 17:55 Modified: 28 Feb 2013 11:45
Reporter: Vadim TKACHENKO Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S5 (Performance)
Version:5.1.38 OS:Any
Assigned to: CPU Architecture:Any

[7 Oct 2012 17:55] Vadim TKACHENKO
Description:
I am creating schema for tpcc-mysql benchmark (2500W), and I am trying to create indexes after I loaded data.
It seems MySQL locked itself, as there is no activity for 54112 sec
and thread stays in "System lock"

mysql> show processlist;
+----+------+-----------+-----------+---------+-------+-------------+---------------------------------------------+
| Id | User | Host      | db        | Command | Time  | State       | Info                                        |
+----+------+-----------+-----------+---------+-------+-------------+---------------------------------------------+
| 23 | root | localhost | NULL      | Query   |     0 | init        | show processlist                            |
| 20 | root | localhost | tpccw2500 | Query   | 54112 | System lock | CREATE INDEX fkey_stock_2 ON stock (s_i_id) |
+----+------+-----------+-----------+---------+-------+-------------+---------------------------------------------+
2 rows in set (0.00 sec)

How to repeat:
tpcc-mysql benchmark,
1. create_table.sql
2. load data
3. add_fkey_idx.sql

system is locked
[9 Oct 2012 5:49] Marko Mäkelä
Hi Vadim,

Can you attach gdb to the hung mysqld and post the "thread apply all backtrace" output so that we see where it is hung?

Could it be due to the metadata lock upgrade timeout, which is 1 year by default? You see, at the start and end of DDL operations (prepare_inplace_alter_table and commit_inplace_alter_table), we will need an exclusive meta-data lock. If some connection holds an open transaction that has accessed the table, then the MDL cannot be upgraded to exclusive.

Thanks to our internal testing, I have fixed a few bugs in the online ALTER TABLE since the 5.6.7 release. This bug does not feel familiar.
[9 Oct 2012 10:42] Marko Mäkelä
Does add_fkey_idx.sql add any foreign keys? If it does, you probably want to temporarily set foreign_key_checks=0 to skip the table-copying (ALGORITHM=COPY).
[9 Oct 2012 14:20] Vadim TKACHENKO
Marco,

I can try again, and if it happens, I will attach gdb.

The script is following,
it seems it stuck on 3rd CREATE INDEX

SET @OLD_UNIQUE_CHECKS=@@UNIQUE_CHECKS, UNIQUE_CHECKS=0;
SET @OLD_FOREIGN_KEY_CHECKS=@@FOREIGN_KEY_CHECKS, FOREIGN_KEY_CHECKS=0;

CREATE INDEX idx_customer ON customer (c_w_id,c_d_id,c_last,c_first);
CREATE INDEX idx_orders ON orders (o_w_id,o_d_id,o_c_id,o_id);
CREATE INDEX fkey_stock_2 ON stock (s_i_id);
CREATE INDEX fkey_order_line_2 ON order_line (ol_supply_w_id,ol_i_id);

ALTER TABLE district  ADD CONSTRAINT fkey_district_1 FOREIGN KEY(d_w_id) REFERENCES warehouse(w_id);
ALTER TABLE customer ADD CONSTRAINT fkey_customer_1 FOREIGN KEY(c_w_id,c_d_id) REFERENCES district(d_w_id,d_id);
ALTER TABLE history  ADD CONSTRAINT fkey_history_1 FOREIGN KEY(h_c_w_id,h_c_d_id,h_c_id) REFERENCES customer(c_w_id,c_d_id,c_id);
ALTER TABLE history  ADD CONSTRAINT fkey_history_2 FOREIGN KEY(h_w_id,h_d_id) REFERENCES district(d_w_id,d_id);
ALTER TABLE new_orders ADD CONSTRAINT fkey_new_orders_1 FOREIGN KEY(no_w_id,no_d_id,no_o_id) REFERENCES orders(o_w_id,o_d_id,o_id);
ALTER TABLE orders ADD CONSTRAINT fkey_orders_1 FOREIGN KEY(o_w_id,o_d_id,o_c_id) REFERENCES customer(c_w_id,c_d_id,c_id);
ALTER TABLE order_line ADD CONSTRAINT fkey_order_line_1 FOREIGN KEY(ol_w_id,ol_d_id,ol_o_id) REFERENCES orders(o_w_id,o_d_id,o_id);
ALTER TABLE order_line ADD CONSTRAINT fkey_order_line_2 FOREIGN KEY(ol_supply_w_id,ol_i_id) REFERENCES stock(s_w_id,s_i_id);
ALTER TABLE stock ADD CONSTRAINT fkey_stock_1 FOREIGN KEY(s_w_id) REFERENCES warehouse(w_id);
ALTER TABLE stock ADD CONSTRAINT fkey_stock_2 FOREIGN KEY(s_i_id) REFERENCES item(i_id);

SET FOREIGN_KEY_CHECKS=@OLD_FOREIGN_KEY_CHECKS;
SET UNIQUE_CHECKS=@OLD_UNIQUE_CHECKS;
[10 Oct 2012 12:35] Marc ALFF
Vadim,

if you have a connection on the server when this happens, could you also provide the content of the performance schema tables ?

mutex_instances, rwlock_instances will show if locks are held
events_waits_current will show what exactly the blocked thread is waiting for.

Thanks,
-- Marc
[10 Oct 2012 16:39] Vadim TKACHENKO
Loading and creating indexes on 250GB database is not quickest task.
I am trying to repeat it and will how stats if I am able to.
[11 Oct 2012 4:40] Vadim TKACHENKO
Actually it seems it is no lock, but very slow process.
Status "System lock" got me confused.

As you see the thread is working over 15 hours.
I think it is extremely long time for creating index. This threads takes 100% of 1 CPU core.

I did gdb stack trace for this thread:

Thread 5 (Thread 0x7f87ec3f0700 (LWP 3141)):
#0  0x000000000094fa6e in dyn_block_get_used (mtr=0x7f87ec3ebce0, object=0x7f449acf5480, type=1) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/include/dyn0dyn.ic:100
#1  dyn_array_get_element (mtr=0x7f87ec3ebce0, object=0x7f449acf5480, type=1) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/include/dyn0dyn.ic:300
#2  mtr_memo_release (mtr=0x7f87ec3ebce0, object=0x7f449acf5480, type=1) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/mtr/mtr0mtr.cc:364
#3  0x000000000098c96e in btr_leaf_page_release (trx=0x7f3918007038, table=0x7f391804ff10, old_table=0x7f3938023448, new_table=0x7f3938023448, online=true, index=0x7f3918011a40, fts_sort_idx=0x0, psort_info=0x0, files=0x7f391802a0e8, key_numbers=0x7f391800ffb0, n_index=1, add_cols=0x0, col_map=0x0, add_autoinc=18446744073709551615, sequence=..., block=0x7f3966152000 "\002") at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/include/btr0btr.ic:288
#4  row_merge_read_clustered_index (trx=0x7f3918007038, table=0x7f391804ff10, old_table=0x7f3938023448, new_table=0x7f3938023448, online=true, index=0x7f3918011a40, fts_sort_idx=0x0, psort_info=0x0, files=0x7f391802a0e8, key_numbers=0x7f391800ffb0, n_index=1, add_cols=0x0, col_map=0x0, add_autoinc=18446744073709551615, sequence=..., block=0x7f3966152000 "\002") at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/row/row0merge.cc:1417
#5  0x000000000098e74e in row_merge_build_indexes (trx=0x7f3918007038, old_table=0x7f3938023448, new_table=0x7f3938023448, online=true, indexes=0x7f391800ffa8, key_numbers=0x7f391800ffb0, n_indexes=1, table=0x7f391804ff10, add_cols=0x0, col_map=0x0, add_autoinc=18446744073709551615, sequence=...) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/row/row0merge.cc:3467
#6  0x000000000091ab54 in ha_innobase::inplace_alter_table (this=0x7f392801f850, altered_table=0x7f391804ff10, ha_alter_info=0x7f87ec3ed770) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/handler/handler0alter.cc:3686
#7  0x000000000071278f in ha_inplace_alter_table (thd=0x1fc43b000, table_list=0x7f3918004bf0, table=0x7f392801ef70, altered_table=0x7f391804ff10, ha_alter_info=0x7f87ec3ed770, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f87ec3ee490, alter_ctx=0x7f87ec3ec760) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/handler.h:2800
#8  mysql_inplace_alter_table (thd=0x1fc43b000, table_list=0x7f3918004bf0, table=0x7f392801ef70, altered_table=0x7f391804ff10, ha_alter_info=0x7f87ec3ed770, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f87ec3ee490, alter_ctx=0x7f87ec3ec760) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_table.cc:6323
#9  0x00000000007146c5 in mysql_alter_table (thd=0x1fc43b000, new_db=<value optimized out>, new_name=<value optimized out>, create_info=0x7f87ec3eed90, table_list=0x7f3918004bf0, alter_info=0x7f87ec3ee7d0, order_num=0, order=0x0, ignore=false) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_table.cc:7961
#10 0x00000000006c6ec2 in mysql_execute_command (thd=0x1fc43b000) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_parse.cc:3009
#11 0x00000000006c9b7d in mysql_parse (thd=0x1fc43b000, rawbuf=<value optimized out>, length=<value optimized out>, parser_state=<value optimized out>) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_parse.cc:6094
#12 0x00000000006ca9d6 in dispatch_command (command=COM_QUERY, thd=0x1fc43b000, packet=0x1fc515281 "CREATE INDEX fkey_stock_2 ON stock (s_i_id)", packet_length=43) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_parse.cc:1314
#13 0x0000000000697d8f in do_handle_one_connection (thd_arg=<value optimized out>) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_connect.cc:969
#14 0x0000000000697e65 in handle_one_connection (arg=0x1fc546cc0) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_connect.cc:885
#15 0x00000000008fb8fb in pfs_spawn_thread (arg=<value optimized out>) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/perfschema/pfs.cc:1853
#16 0x00007f87efe7d7f1 in start_thread () from /lib64/libpthread.so.0
#17 0x00007f87eebe7ccd in clone () from /lib64/libc.so.6

It seems all time is spent in
#0  dyn_array_get_data_size (mtr=0x7f87ec3ebce0, object=0x7f7e49396a00, type=1) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/include/dyn0dyn.ic:334

and in

#0  dyn_array_get_element (mtr=0x7f87ec3ebce0, object=0x7f4e3840f300, type=1) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/include/dyn0dyn.ic:296
[19 Oct 2012 8:35] Marko Mäkelä
The ha_innobase::inplace_alter_table is where the index creation is taking place. According to the stack trace, the index entries were already sorted and they are being loaded into the index B-tree. The loading is using the routines for inserting a record one at a time. There is room for optimization, for loading a page at a time, since the records are known to be sorted.

If this is an online operation (like it is by default), the table can be read and written concurrently while ha_innobase::inplace_alter_table is executing.

The index creation is single-threaded. CREATE FULLTEXT INDEX is the only exception. It uses a parallel sort.

I guess you could work around this by creating indexes on multiple tables in parallel, from multiple connections.
[19 Oct 2012 17:53] Vadim TKACHENKO
Marco,

Let's consider two scenarios:

First:
1. create tables
2. create indexes
3. load data

Second:
1. create tables
2. load data
3. create indexes

Usually, and especially with recent FAST INDEX creation second scenario
is faster.

But with 5.6 I see it changed. I did not perform measurements, but
it seems that first scenario performs much faster,
as in second CREATE INDEXES is very slow.
[1 Nov 2012 6:04] Marko Mäkelä
Sorry, I was misreading the stack trace.

It is not stuck in the bulk insert of the sorted index entries, but in the clustered index scan (copying the data to the sort buffer).

I don't think that this code path should have been changed that much from the 5.1 plugin. One thing that has changed (for the better) is that page switches are supposed to be faster during the clustered index scan. On page switch, we no longer dive to the next page, but follow the next-page pointer and invoke btr_leaf_page_release() on the previous page. Maybe this function is being slow for some reason?

You can disable this index scan optimization by replacing rw_lock_get_waiters() with false in row0merge.cc. Does this fix the regression?

For online index creation, it is the DML that will do some more work. But, your test case apparently does not involve any concurrent DML. Can you confirm that adding LOCK=EXCLUSIVE or LOCK=SHARED to the ALTER TABLE or CREATE INDEX statement does not affect the speed?
[1 Nov 2012 15:40] Vadim TKACHENKO
Macro,

I will check when I have a chance again, now I moved to different task.
[9 Nov 2012 8:18] Marko Mäkelä
Sorry, I meant true, not false:

=== modified file 'storage/innobase/row/row0merge.cc'
--- storage/innobase/row/row0merge.cc	revid:marc.alff@oracle.com-20121108214031-9f1941clnva250im
+++ storage/innobase/row/row0merge.cc	2012-11-09 08:15:58 +0000
@@ -1285,7 +1285,7 @@ row_merge_read_clustered_index(
 				"ib_purge_on_create_index_page_switch",
 				dbug_run_purge = true;);
 
-			if (dbug_run_purge
+			if (true
 			    || rw_lock_get_waiters(
 				    dict_index_get_lock(clust_index))) {
 				/* There are waiters on the clustered

I do not see any significant difference in my small test, dropping and creating indexes on a table. The ADD INDEX run time varies between 7 and 11 seconds, I guess depending on I/O speed.
[9 Nov 2012 8:53] Marko Mäkelä
I performed the same test on a 5.5 build. It is taking around 5 seconds instead of 7 seconds, and the variance in the execution time is only around 1 second.
[9 Nov 2012 10:13] Marko Mäkelä
Sorry, please disregard my previous comment. My 5.6 tree was built WITH_VALGRIND and the 5.5 tree was built without it. Doing an apples-to-apples comparison, I get similar performance (5 seconds to create indexes) with both versions.

Do you see a regression from 5.5 to 5.6?
[9 Nov 2012 15:06] Vadim TKACHENKO
Marko,

I think you are right.
My confusion comes from the fact that in 5.5
these indexes are created by FAST INDEX method,
and now these indexes are handled by TABLE COPY.
In the result the same procedure in 5.6 is much slower than in 5.5,
and to achieve the same performance in 5.6, I need to change application.
[16 Nov 2012 14:29] Marko Mäkelä
Vadim, I do not understand your comment.
Your stack trace is from the 'fast index creation' code path.
[17 Jan 2013 12:15] Marko Mäkelä
There is room for improving the efficiency of CREATE INDEX, but I do not think there is any performance regression from 5.1 plugin to 5.6. These improvements are nontrivial to implement.

The stack trace could point to Bug#68069 mtr_memo_release and dyn_array together are very inefficient.
[31 Jan 2013 10:15] Jimmy Yang
Vadim, could you please verify is this still a problem or not? And the way to reproduce it.
[28 Feb 2013 11:45] Erlend Dahl
Correcting status, setting to "can't repeat" for the time being.

The bug can be reopened if more information is available.