[MDEV-7370] Server deadlocks on renaming a table for which persistent statistics exists Created: 2014-12-25  Updated: 2015-11-19  Resolved: 2015-11-18

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.0
Fix Version/s: 10.0.23

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Fixed Votes: 3
Labels: eits


 Description   

With the following test case, server hangs seemingly forever on RENAME TABLE. Reducing lock_wait_timeout does not help. Happens both with MyISAM and InnoDB. If persistent statistics is not collected, there is no hang up. Reproducible on debug and release builds.

create database db1;
create database db2;
use db1;
create table t1 (i int);
analyze table t1 persistent for all;
rename table t1 to db2.t1;
 
# Cleanup
drop database db1;
drop database db2;

Stack trace from 10.0 revno 4543 on the hanging server

#0  __pthread_getspecific (key=3) at pthread_getspecific.c:32
#1  0x0000000000e49570 in my_thread_var_dbug () at 10.0/mysys/my_thr_init.c:432
#2  0x0000000000e65dd8 in code_state () at 10.0/dbug/dbug.c:350
#3  0x0000000000e682ba in _db_pargs_ (_line_=409, keyword=0x1129515 "mutex") at 10.0/dbug/dbug.c:1228
#4  0x0000000000e50314 in safe_mutex_unlock (mp=0x7f42bf81fd28, file=0x1124638 "10.0/mysys/mf_keycache.c", line=2879) at 10.0/mysys/thr_mutex.c:409
#5  0x0000000000e2c6d9 in inline_mysql_mutex_unlock (that=0x7f42bf81fd28, src_file=0x1124638 "10.0/mysys/mf_keycache.c", src_line=2879) at 10.0/include/mysql/p
si/mysql_thread.h:761
#6  0x0000000000e30c48 in simple_key_cache_read (keycache=0x7f42bf81fc70, file=61, filepos=6144, level=3, buff=0x7f42b86b9cb0 "", length=1024, block_length=3072, return_buffer=1) at /home/elens
t/bzr/10.0/mysys/mf_keycache.c:2879
#7  0x0000000000e34d0f in key_cache_read (keycache=0x7f42bf827270, file=61, filepos=4096, level=3, buff=0x7f42b86b94b0 "", length=3072, block_length=3072, return_buffer=1) at 1
0.0/mysys/mf_keycache.c:6211
#8  0x0000000000dd9943 in _mi_fetch_keypage (info=0x7f42b86b9070, keyinfo=0x7f42b84a0e70, page=4096, level=3, buff=0x7f42b86b94b0 "", return_buffer=1) at 10.0/storage/myisam/mi
_page.c:32
#9  0x0000000000ddd20d in _mi_search (info=0x7f42b86b9070, keyinfo=0x7f42b84a0e70, key=0x7f42b86bb15e "\003db1\002t1\001i", key_len=7, nextflag=1, pos=4096) at 10.0/storage/myisam/mi_search.c:85
#10 0x0000000000dfcdc1 in mi_rkey (info=0x7f42b86b9070, buf=0x7f42b8622088 "\337\003db1\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\002t1\217\217\217"..., inx=0, key=0x7f42c2299d80 "\003", keypart_map=3, search_flag=HA_READ_KEY_EXACT) at 10.0/storage/myisam/mi_rkey.c:99
#11 0x0000000000da7112 in ha_myisam::index_read_idx_map (this=0x7f42b847f088, buf=0x7f42b8622088 "\337\003db1\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\002t1\217\217\217"..., index=0, key=0x7f42c2299d80 "\003", keypart_map=3, find_flag=HA_READ_KEY_EXACT) at 10.0/storage/myisam/ha_myisam.cc:1743
#12 0x000000000086e45c in handler::ha_index_read_idx_map (this=0x7f42b847f088, buf=0x7f42b8622088 "\337\003db1\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\002t1\217\217\217"..., index=0, key=0x7f42c2299d80 "\003", keypart_map=3, find_flag=HA_READ_KEY_EXACT) at 10.0/sql/handler.cc:2614
#13 0x00000000007164be in Stat_table::find_next_stat_for_prefix (this=0x7f42c229aac0, prefix_parts=2) at 10.0/sql/sql_statistics.cc:493
#14 0x00000000007146bf in rename_table_in_stat_tables (thd=0x7f42baf2f070, db=0x7f42c229be00, tab=0x7f42c229bdf0, new_db=0x7f42c229be00, new_tab=0x7f42c229bde0) at 10.0/sql/sql_statistics.cc:3294
#15 0x00000000006a0267 in do_rename (thd=0x7f42baf2f070, ren_table=0x7f42b84141a0, new_db=0x7f42b8414160 "db2", new_table_name=0x7f42b8414168 "t1", new_table_alias=0x7f42b8414780 "t1", skip_error=false) at 10.0/sql/sql_rename.cc:283
#16 0x00000000006a0461 in rename_tables (thd=0x7f42baf2f070, table_list=0x7f42b84141a0, skip_error=false) at 10.0/sql/sql_rename.cc:358
#17 0x000000000069fe39 in mysql_rename_tables (thd=0x7f42baf2f070, table_list=0x7f42b84141a0, silent=false) at 10.0/sql/sql_rename.cc:153
#18 0x00000000006836b4 in execute_rename_table (thd=0x7f42baf2f070, first_table=0x7f42b84141a0, all_tables=0x7f42b84141a0) at 10.0/sql/sql_parse.cc:5331
#19 0x000000000067cd8c in mysql_execute_command (thd=0x7f42baf2f070) at 10.0/sql/sql_parse.cc:3172
#20 0x00000000006859bd in mysql_parse (thd=0x7f42baf2f070, rawbuf=0x7f42b8414088 "rename table t1 to db2.t1", length=25, parser_state=0x7f42c229d610) at 10.0/sql/sql_parse.cc:6407
#21 0x00000000006787b2 in dispatch_command (command=COM_QUERY, thd=0x7f42baf2f070, packet=0x7f42bbff6071 "rename table t1 to db2.t1", packet_length=25) at 10.0/sql/sql_parse.cc:1299
#22 0x0000000000677b57 in do_command (thd=0x7f42baf2f070) at 10.0/sql/sql_parse.cc:996



 Comments   
Comment by Daniel Black [ 2015-10-29 ]

Any chance of this making it into a sprint soon?

MariaDB [(none)]> show processlist;
+----+------+-----------+------+---------+------+----------------------+--------------------------------------------------------------------+----------+
| Id | User | Host      | db   | Command | Time | State                | Info                                                               | Progress |
+----+------+-----------+------+---------+------+----------------------+--------------------------------------------------------------------+----------+
|  5 | root | localhost | NULL | Query   |   42 | After opening tables | RENAME TABLE ibis_staging.domain_access TO ibis_test.domain_access |    0.000 |
|  6 | root | localhost | NULL | Query   |    0 | init                 | show processlist                                                   |    0.000 |
+----+------+-----------+------+---------+------+----------------------+--------------------------------------------------------------------+----------+
2 rows in set (0.00 sec)
 
MariaDB [(none)]>
MariaDB [(none)]> select * from information_schema.metadata_lock_info;
+-----------+-------------------------+-----------------+----------------------+--------------+---------------+
| THREAD_ID | LOCK_MODE               | LOCK_DURATION   | LOCK_TYPE            | TABLE_SCHEMA | TABLE_NAME    |
+-----------+-------------------------+-----------------+----------------------+--------------+---------------+
|         5 | MDL_INTENTION_EXCLUSIVE | MDL_STATEMENT   | Global read lock     |              |               |
|         5 | MDL_INTENTION_EXCLUSIVE | MDL_TRANSACTION | Schema metadata lock | ibis_test    |               |
|         5 | MDL_SHARED_WRITE        | MDL_TRANSACTION | Table metadata lock  | mysql        | index_stats   |
|         5 | MDL_SHARED_WRITE        | MDL_TRANSACTION | Table metadata lock  | mysql        | table_stats   |
|         5 | MDL_EXCLUSIVE           | MDL_TRANSACTION | Table metadata lock  | ibis_staging | domain_access |
|         5 | MDL_INTENTION_EXCLUSIVE | MDL_TRANSACTION | Schema metadata lock | ibis_staging |               |
|         5 | MDL_EXCLUSIVE           | MDL_TRANSACTION | Table metadata lock  | ibis_test    | domain_access |
|         5 | MDL_SHARED_WRITE        | MDL_TRANSACTION | Table metadata lock  | mysql        | column_stats  |
+-----------+-------------------------+-----------------+----------------------+--------------+---------------+
8 rows in set (0.00 sec)

lsof -p 15772 | grep mysql/
 
mysqld  15772 mysql  mem    REG              202,1       10728       321 /usr/lib/mysql/plugin/query_response_time.so
mysqld  15772 mysql  mem    REG              202,1       10552     14555 /usr/lib/mysql/plugin/metadata_lock_info.so
mysqld  15772 mysql  mem    REG              202,1       10648     14778 /usr/lib/mysql/plugin/sql_errlog.so
mysqld  15772 mysql  mem    REG              202,1     1358656     14867 /usr/lib/mysql/plugin/ha_connect.so
mysqld  15772 mysql   15uW  REG             202,80    14680064    299539 /srv/mysqldata/mysql/innodb_index_stats.ibd
mysqld  15772 mysql   16uW  REG             202,80      245760    299537 /srv/mysqldata/mysql/innodb_table_stats.ibd
mysqld  15772 mysql   29w   REG              202,1     2167223    135538 /var/log/mysql/slow.log
mysqld  15772 mysql   30u   REG             202,80        1024       158 /srv/mysqldata/mysql/servers.MYI
mysqld  15772 mysql   31u   REG             202,80           0       159 /srv/mysqldata/mysql/servers.MYD
mysqld  15772 mysql   35u   REG             202,80        2048    299541 /srv/mysqldata/mysql/host.MYI
mysqld  15772 mysql   36u   REG             202,80           0    299542 /srv/mysqldata/mysql/host.MYD
mysqld  15772 mysql   37u   REG             202,80        4096    299526 /srv/mysqldata/mysql/user.MYI
mysqld  15772 mysql   38u   REG             202,80        1236    299557 /srv/mysqldata/mysql/user.MYD
mysqld  15772 mysql   39u   REG             202,80        9216       147 /srv/mysqldata/mysql/db.MYI
mysqld  15772 mysql   40u   REG             202,80        5688       156 /srv/mysqldata/mysql/db.MYD
mysqld  15772 mysql   41u   REG             202,80       10240    299522 /srv/mysqldata/mysql/proxies_priv.MYI
mysqld  15772 mysql   42u   REG             202,80        1269    299523 /srv/mysqldata/mysql/proxies_priv.MYD
mysqld  15772 mysql   43u   REG             202,80        4096       149 /srv/mysqldata/mysql/roles_mapping.MYI
mysqld  15772 mysql   44u   REG             202,80           0       150 /srv/mysqldata/mysql/roles_mapping.MYD
mysqld  15772 mysql   45u   REG             202,80        4096    299555 /srv/mysqldata/mysql/tables_priv.MYI
mysqld  15772 mysql   46u   REG             202,80           0    299556 /srv/mysqldata/mysql/tables_priv.MYD
mysqld  15772 mysql   47u   REG             202,80        4096       164 /srv/mysqldata/mysql/columns_priv.MYI
mysqld  15772 mysql   48u   REG             202,80           0       165 /srv/mysqldata/mysql/columns_priv.MYD
mysqld  15772 mysql   49u   REG             202,80        4096    299535 /srv/mysqldata/mysql/procs_priv.MYI
mysqld  15772 mysql   50u   REG             202,80           0    299540 /srv/mysqldata/mysql/procs_priv.MYD
mysqld  15772 mysql   52u   REG             202,80        2048    299536 /srv/mysqldata/mysql/event.MYI
mysqld  15772 mysql   53u   REG             202,80           0    299538 /srv/mysqldata/mysql/event.MYD
mysqld  15772 mysql   54uW  REG             202,80       98304    299553 /srv/mysqldata/mysql/gtid_slave_pos.ibd
mysqld  15772 mysql  205u   REG             202,80       51200    299544 /srv/mysqldata/mysql/table_stats.MYI
mysqld  15772 mysql  207u   REG             202,80       45444    299545 /srv/mysqldata/mysql/table_stats.MYD
mysqld  15772 mysql  208u   REG             202,80      289792    299547 /srv/mysqldata/mysql/column_stats.MYI
mysqld  15772 mysql  209u   REG             202,80     2003952    299548 /srv/mysqldata/mysql/column_stats.MYD
mysqld  15772 mysql  210u   REG             202,80      550912    299550 /srv/mysqldata/mysql/index_stats.MYI
mysqld  15772 mysql  211u   REG             202,80     1711376    299551 /srv/mysqldata/mysql/index_stats.MYD

Comment by Daniel Black [ 2015-11-08 ]

Even after process killed off, process and locks remain.

MariaDB [test]> show processlist;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    8
Current database: test
 
+----+------+-----------+------+---------+------+----------------------+---------------------------+----------+
| Id | User | Host      | db   | Command | Time | State                | Info                      | Progress |
+----+------+-----------+------+---------+------+----------------------+---------------------------+----------+
|  4 | root | localhost | test | Killed  |  583 | After opening tables | rename table x to test1.x |    0.000 |
|  8 | root | localhost | test | Query   |    0 | init                 | show processlist          |    0.000 |
+----+------+-----------+------+---------+------+----------------------+---------------------------+----------+

Clean shutdown also not possible:

151108 16:00:27 [Note] sql/mysqld: Normal shutdown
151108 16:00:27 [Note] Event Scheduler: Purging the queue. 0 events
151108 16:00:47 [Warning] sql/mysqld: Forcing close of thread 4  user: 'root'
151108 16:00:47 [ERROR] mysqld: Got an error writing communication packets

Comment by Daniel Black [ 2015-11-08 ]

Stuck in this endless loop:

 (gdb) break sql_statistics.cc:3296
Breakpoint 1 at 0x6a5590: file /home/dan/software_projects/mariadb-server/sql/sql_statistics.cc, line 3296.
(gdb) c
Continuing.
[New Thread 0x7fef510f4700 (LWP 28730)]
[Switching to Thread 0x7fef510f4700 (LWP 28730)]
 
Breakpoint 1, rename_table_in_stat_tables (thd=0x7fef45e78008, db=0x7fef510f1f50, tab=0x7fef510f1f40, new_db=0x7fef510f1f50, new_tab=0x7fef510f1f30)
    at /home/dan/software_projects/mariadb-server/sql/sql_statistics.cc:3297
3297      stat_table= tables[COLUMN_STAT].table;
(gdb) n
3298      Column_stat column_stat(stat_table, db, tab);
(gdb) n
3299      column_stat.set_full_table_name();
(gdb) p column_stat
$1 = {<Stat_table> = {_vptr.Stat_table = 0xcba8f0 <vtable for Column_stat+16>, stat_file = 0x7fef304c4b20, stat_key_length = 582, record = {0x7fef3044d020 "\377\003db1", 
      0x7fef3044d978 "\377"}, stat_key_idx = 0, stat_table = 0x7fef30504608, stat_key_info = 0x7fef30468288, table = 0x316264, table_share = 0x0, db_name = 0x7fef510f1f50, 
    table_name = 0x7fef510f1f40}, db_name_field = 0x7fef30433080, table_name_field = 0x7fef30433150, column_name_field = 0x7fef30433220, table_field = 0x18e}
(gdb) n
3300      while (column_stat.find_next_stat_for_prefix(2))
(gdb) p column_stat
$2 = {<Stat_table> = {_vptr.Stat_table = 0xcba8f0 <vtable for Column_stat+16>, stat_file = 0x7fef304c4b20, stat_key_length = 582, record = {0x7fef3044d020 "\377\003db1", 
      0x7fef3044d978 "\377"}, stat_key_idx = 0, stat_table = 0x7fef30504608, stat_key_info = 0x7fef30468288, table = 0x316264, table_share = 0x0, db_name = 0x7fef510f1f50, 
    table_name = 0x7fef510f1f40}, db_name_field = 0x7fef30433080, table_name_field = 0x7fef30433150, column_name_field = 0x7fef30433220, table_field = 0x18e}
(gdb) s
Stat_table::find_next_stat_for_prefix (this=0x7fef510f0bc0, prefix_parts=2) at /home/dan/software_projects/mariadb-server/sql/sql_statistics.cc:487
487         uint prefix_key_length= 0;
(gdb) n
488         for (uint i= 0; i < prefix_parts; i++)
(gdb) n
489           prefix_key_length+= stat_key_info->key_part[i].store_length;
(gdb) n
488         for (uint i= 0; i < prefix_parts; i++)
(gdb) n
489           prefix_key_length+= stat_key_info->key_part[i].store_length;
(gdb) n
488         for (uint i= 0; i < prefix_parts; i++)
(gdb) n
490         key_copy(key, record[0], stat_key_info, prefix_key_length);
(gdb) p prefix_key_length
$3 = 388
(gdb) p record
$4 = {0x7fef3044d020 "\377\003db1", 0x7fef3044d978 "\377"}
(gdb) p record[0]
$5 = (uchar *) 0x7fef3044d020 "\377\003db1"
(gdb) p stat_key_info
$6 = (KEY *) 0x7fef30468288
(gdb) p *stat_key_info
$7 = {key_length = 582, flags = 41, user_defined_key_parts = 3, usable_key_parts = 3, ext_key_parts = 3, ext_key_flags = 41, ext_key_part_map = 0, block_size = 3072, name_length = 7, 
  algorithm = HA_KEY_ALG_UNDEF, is_statistics_from_stat_tables = false, {parser = 0x0, parser_name = 0x0}, key_part = 0x7fef30468330, name = 0x7fef30432d41 "PRIMARY", 
  cache_name = 0x7fef30467748 "mysql", rec_per_key = 0x7fef30432d50, read_stats = 0x0, collected_stats = 0x0, handler = {bdb_return_if_eq = 0}, table = 0x7fef30504608, comment = {str = 0x0, 
    length = 0}, option_list = 0x0, option_struct = 0x0}
(gdb) n
[New Thread 0x7fef510ab700 (LWP 28808)]
491         key_part_map prefix_map= (key_part_map) ((1 << prefix_parts) - 1);
(gdb) p *key
$8 = 3 '\003'
(gdb) p key
$9 = "\003\000db1", '\000' <repeats 189 times>, "\002\000t1", '\000' <repeats 194 times>...
(gdb) n
492         return !stat_file->ha_index_read_idx_map(record[0], stat_key_idx, key,
(gdb) n
493                                                  prefix_map, HA_READ_KEY_EXACT);
(gdb) n
494       }
(gdb) n
rename_table_in_stat_tables (thd=0x7fef45e78008, db=0x7fef510f1f50, tab=0x7fef510f1f40, new_db=0x7fef510f1f50, new_tab=0x7fef510f1f30)
    at /home/dan/software_projects/mariadb-server/sql/sql_statistics.cc:3302
3302        err= column_stat.update_table_name_key_parts(new_db, new_tab);
(gdb) p err
$10 = 0
(gdb) p column_stat
$11 = {<Stat_table> = {_vptr.Stat_table = 0xcba8f0 <vtable for Column_stat+16>, stat_file = 0x7fef304c4b20, stat_key_length = 582, record = {0x7fef3044d020 "\337\003db1",
      0x7fef3044d978 "\377"}, stat_key_idx = 0, stat_table = 0x7fef30504608, stat_key_info = 0x7fef30468288, table = 0x316264, table_share = 0x0, db_name = 0x7fef510f1f50,
    table_name = 0x7fef510f1f40}, db_name_field = 0x7fef30433080, table_name_field = 0x7fef30433150, column_name_field = 0x7fef30433220, table_field = 0x18e}
(gdb) n
3303        if (err & !rc)
(gdb) n
3305        column_stat.set_full_table_name();
(gdb) n
3300      while (column_stat.find_next_stat_for_prefix(2))
(gdb) p column_stat
$12 = {<Stat_table> = {_vptr.Stat_table = 0xcba8f0 <vtable for Column_stat+16>, stat_file = 0x7fef304c4b20, stat_key_length = 582, record = {0x7fef3044d020 "\337\003db1",
      0x7fef3044d978 "\337\003db1"}, stat_key_idx = 0, stat_table = 0x7fef30504608, stat_key_info = 0x7fef30468288, table = 0x316264, table_share = 0x0, db_name = 0x7fef510f1f50,
    table_name = 0x7fef510f1f40}, db_name_field = 0x7fef30433080, table_name_field = 0x7fef30433150, column_name_field = 0x7fef30433220, table_field = 0x18e}
(gdb) n
3302        err= column_stat.update_table_name_key_parts(new_db, new_tab);
(gdb) p column_stat
$13 = {<Stat_table> = {_vptr.Stat_table = 0xcba8f0 <vtable for Column_stat+16>, stat_file = 0x7fef304c4b20, stat_key_length = 582, record = {0x7fef3044d020 "\337\003db1",
      0x7fef3044d978 "\337\003db1"}, stat_key_idx = 0, stat_table = 0x7fef30504608, stat_key_info = 0x7fef30468288, table = 0x316264, table_share = 0x0, db_name = 0x7fef510f1f50,
    table_name = 0x7fef510f1f40}, db_name_field = 0x7fef30433080, table_name_field = 0x7fef30433150, column_name_field = 0x7fef30433220, table_field = 0x18e}

Comment by Sergei Petrunia [ 2015-11-16 ]

Stack trace of where it is stuck:

(gdb) wher
  #0  handler::ha_index_read_idx_map (this=0x7fff5802f0d8, buf=0x7fff580300d8
  "..." , index=0, key=0x7ffff42fe3c0 "\003", keypart_map=3, find_flag=HA_READ_KEY_EXACT) at /home/psergey/dev-git/10.1-dbg3/sql/handler.cc:2645
  #1  0x0000555555aeffee in Stat_table::find_next_stat_for_prefix (this=0x7ffff4300250, prefix_parts=2) at /home/psergey/dev-git/10.1-dbg3/sql/sql_statistics.cc:493
  #2  0x0000555555aee239 in rename_table_in_stat_tables (thd=0x55555aac6a80, db=0x7ffff4300450, tab=0x7ffff4300460, new_db=0x7ffff4300450, new_tab=0x7ffff4300470) at /home/psergey/dev-git/10.1-dbg3/sql/sql_statistics.cc:3300
  #3  0x0000555555a7346c in do_rename (thd=0x55555aac6a80, ren_table=0x7fff58007530, new_db=0x7fff580074f0 "db2", new_table_name=0x7fff580074f8 "t1", new_table_alias=0x7fff58007b18 "t1", skip_error=false) at /home/psergey/dev-git/10.1-dbg3/sql/sql_rename.cc:278
  #4  0x0000555555a73669 in rename_tables (thd=0x55555aac6a80, table_list=0x7fff58007530, skip_error=false) at /home/psergey/dev-git/10.1-dbg3/sql/sql_rename.cc:353
  #5  0x0000555555a73017 in mysql_rename_tables (thd=0x55555aac6a80, table_list=0x7fff58007530, silent=false) at /home/psergey/dev-git/10.1-dbg3/sql/sql_rename.cc:153
  #6  0x0000555555a4bb27 in mysql_execute_command (thd=0x55555aac6a80) at /home/psergey/dev-git/10.1-dbg3/sql/sql_parse.cc:3615
  #7  0x0000555555a57497 in mysql_parse (thd=0x55555aac6a80, rawbuf=0x7fff58007418 "rename table t1 to db2.t1", length=25, parser_state=0x7ffff4301100) at /home/psergey/dev-git/10.1-dbg3/sql/sql_parse.cc:7282
  #8  0x0000555555a4607e in dispatch_command (command=COM_QUERY, thd=0x55555aac6a80, packet=0x55555aacd0e1 "rename table t1 to db2.t1", packet_length=25) at /home/psergey/dev-git/10.1-dbg3/sql/sql_parse.cc:1488
  #9  0x0000555555a44dbf in do_command (thd=0x55555aac6a80) at /home/psergey/dev-git/10.1-dbg3/sql/sql_parse.cc:1110
  #10 0x0000555555b760f6 in do_handle_one_connection (thd_arg=0x55555aac6a80) at /home/psergey/dev-git/10.1-dbg3/sql/sql_connect.cc:1350
  #11 0x0000555555b75e47 in handle_one_connection (arg=0x55555aac6a80) at /home/psergey/dev-git/10.1-dbg3/sql/sql_connect.cc:1262
  #12 0x00007ffff691de9a in start_thread (arg=0x7ffff4302700) at pthread_create.c:308
  #13 0x00007ffff604e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

It is enumerating a lot of rows:

(gdb) p index_rows_read[index]
  $132 = 453061
(gdb) p this
  $133 = (handler * const) 0x7fff5802f0d8
(gdb) p table->alias.Ptr
  $134 = 0x7fff58028820 "column_stats"
(gdb) p index
  $135 = 0

Comment by Sergei Petrunia [ 2015-11-16 ]

The following happens:
We are updating table statistics. We search for "db1.t1.i1" in
mysql.column_stats table.

We update the row to be "db2.t1.i1"

We try to continue searching for other row, but we keep getting the same row
that refers to "db1.t1.i1".

I think, the bug is in that we're trying to make updates to the index that
we're using to do scan. When UPDATE command detects it is about to do so, it
buffers rowids and then does the updates (check used_key_is_modified in
sql_update.cc).

Comment by Daniel Black [ 2015-11-17 ]

Renaming tables within the same database works without a problem.

MariaDB [test]> rename table x to y;
Query OK, 0 rows affected (0.00 sec)
 
MariaDB [test]> rename table y to test.z;
Query OK, 0 rows affected (0.01 sec)

Found at least one case where a table rename works across database:

MariaDB [test]> rename table z to t2.y;
Query OK, 0 rows affected (0.00 sec)
{nofomrat}
 
Does rename_table_in_stat_tables work the same way as the sql 'update mysql.column_stats set db_name='destdb',table_name='desttable' where db_name='source_db' and table_name='source_table';
 
Interesting when mysql.column_stats is changed to innodb for a case where it lock waited:

------------------------------------------------------------------------------------

Id User Host db Command Time State Info Progress

------------------------------------------------------------------------------------

6 root localhost t2 Query 141 After opening tables rename table x to test.x 0.000
7 root localhost NULL Query 0 init show processlist 0.000

------------------------------------------------------------------------------------

------------
TRANSACTIONS
------------
Trx id counter 1852
Purge done for trx's n:o < 1850 undo n:o < 0 state: running but idle
History list length 19
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 7, OS thread handle 0x7f4e4fd62700, query id 41 localhost root init
show engine innodb status
---TRANSACTION 1795, not started
MySQL thread id 1, OS thread handle 0x7f4e4fe3d700, query id 0 Waiting for background binlog tasks
---TRANSACTION 1851, ACTIVE 31 sec starting index read
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 6387333
MySQL thread id 6, OS thread handle 0x7f4e4fdab700, query id 38 localhost root After opening tables
rename table x to test.x
Trx #rec lock waits 0 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC

 

Comment by Sergei Petrunia [ 2015-11-17 ]

http://lists.askmonty.org/pipermail/commits/2015-November/008639.html

Comment by Sergei Petrunia [ 2015-11-17 ]

sanja, can you please review the patch?

Comment by Oleksandr Byelkin [ 2015-11-17 ]

Ok, to push, but it will be better to put cleanup in destructor.

Comment by Daniel Black [ 2015-11-18 ]

Looks good, thank you both. I've tested the patch on 10.0 and 10.1. Hoping 10.0 is the fix branch.

As a test case suggestion to cover a bit more I'd rename the table name as you are renaming to a different database.

Comment by Sergei Petrunia [ 2015-11-18 ]

danblack, thanks for pointing out about the 10.0 being the target. For some reason I had committed the previous patch against 10.1.

Also added a test that renames a table within the same database.

Comment by Sergei Petrunia [ 2015-11-18 ]

Pushed the fix into 10.0 tree.

Comment by Daniel Black [ 2015-11-19 ]

.bq Pushed the fix into 10.0 tree.

thanks. I hadn't thought about doing a ALTER TABLE to trigger a rename:

I did a quick check that adding/removing columns during the rename results in no additional columns during the rename and works as expected:

MariaDB [(none)]> create database t2;
Query OK, 1 row affected (0.00 sec)
 
MariaDB [(none)]> use test;
Database changed
MariaDB [test]> create table t1 (x int, y varchar(30) default 'vodo');
Query OK, 0 rows affected (0.00 sec)
 
MariaDB [test]> insert into t1 values (2,'so'), (6, 'check'), (9, 'rocket');
Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0
 
MariaDB [test]> analyze table t1 persistent for all;
+---------+---------+----------+-----------------------------------------+
| Table   | Op      | Msg_type | Msg_text                                |
+---------+---------+----------+-----------------------------------------+
| test.t1 | analyze | status   | Engine-independent statistics collected |
| test.t1 | analyze | status   | OK                                      |
+---------+---------+----------+-----------------------------------------+
2 rows in set (0.00 sec)
 
MariaDB [test]> select * from mysql.column_stats;
+---------+------------+-------------+-----------+-----------+-------------+------------+---------------+-----------+-----------+-----------+
| db_name | table_name | column_name | min_value | max_value | nulls_ratio | avg_length | avg_frequency | hist_size | hist_type | histogram |
+---------+------------+-------------+-----------+-----------+-------------+------------+---------------+-----------+-----------+-----------+
| test    | t1         | x           | 2         | 9         |      0.0000 |     4.0000 |        1.0000 |         0 | NULL      | NULL      |
| test    | t1         | y           | check     | so        |      0.0000 |     4.3333 |        1.0000 |         0 | NULL      | NULL      |
+---------+------------+-------------+-----------+-----------+-------------+------------+---------------+-----------+-----------+-----------+
2 rows in set (0.00 sec)
 
MariaDB [test]> alter table t1 add z varchar(30) default 'china', drop x, rename t2.t2;
Query OK, 0 rows affected (0.01 sec)
Records: 0  Duplicates: 0  Warnings: 0
 
MariaDB [test]> select * from mysql.column_stats;
+---------+------------+-------------+-----------+-----------+-------------+------------+---------------+-----------+-----------+-----------+
| db_name | table_name | column_name | min_value | max_value | nulls_ratio | avg_length | avg_frequency | hist_size | hist_type | histogram |
+---------+------------+-------------+-----------+-----------+-------------+------------+---------------+-----------+-----------+-----------+
| t2      | t2         | y           | check     | so        |      0.0000 |     4.3333 |        1.0000 |         0 | NULL      | NULL      |
+---------+------------+-------------+-----------+-----------+-------------+------------+---------------+-----------+-----------+-----------+
1 row in set (0.00 sec)

Generated at Thu Feb 08 07:19:04 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.