[MDEV-5875] Server hangs on single-threaded operation with XtraDB table with --innodb_priority_cleaner=ON - JIRA

Details

Type: Bug
Status: Closed
Priority: Minor
Resolution: Cannot Reproduce
Affects Version/s: 10.0.9
Fix Version/s: 10.0.11
Component/s: None
Labels:
None

Description

Server hangs on a single-threaded DDL or DML if it's run with innodb_priority_cleaner=ON.
Could not reproduce on Percona server 5.6.
Maybe MariaDB server misses something to work with XtraDB's thread priority locks – if so, the variables should probably be disabled for now.

RQG command line:

perl ./runall-new.pl --grammar=conf/temporal/temporal_functions.yy --gendata=conf/temporal/temporal_functions.zz  --duration=300 --threads=1 --queries=100M --basedir=10.0 --vardir=/home/elenst/test_results/analyze --mysqld=--innodb_priority_cleaner=ON --engine=InnoDB

In the middle of creating tables it stops (hangs). There are many tables created in this test, so it can be long.

Stack trace from the running server:

Thread 2 (Thread 0x7fe9b5504700 (LWP 11764)):
#0  0x00007fe9b47c7d84 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x0000000000bda3bc in os_cond_wait (cond=0x7fe995d9b2c0, fast_mutex=0x7fe995d9b280) at 10.0/storage/xtradb/os/os0sync.cc:214
#2  0x0000000000bda8e4 in os_event_wait_low (event=0x7fe995d9b280, reset_sig_count=9) at 10.0/storage/xtradb/os/os0sync.cc:610
#3  0x0000000000c9e2e8 in sync_array_wait_event (arr=0x7fe9b0348600, index=0) at 10.0/storage/xtradb/sync/sync0arr.cc:433
#4  0x0000000000ca318a in mutex_spin_wait (_mutex=0x7fe9b3014fc8, high_priority=false, file_name=0x113f528 "10.0/storage/xtradb/log/log0log.cc", line=1575) at 10.0/storage/xtradb/sync/sync0sync.cc:671
#5  0x0000000000bb2628 in mutex_enter_func (mutex=0x7fe9b3014fc8, file_name=0x113f528 "10.0/storage/xtradb/log/log0log.cc", line=1575, priority=IB_DEFAULT_PRIO) at 10.0/storage/xtradb/include/sync0sync.ic:316
#6  0x0000000000bb26dc in pfs_mutex_enter_func (mutex=0x7fe9b3014fc8, file_name=0x113f528 "10.0/storage/xtradb/log/log0log.cc", line=1575, priority=IB_DEFAULT_PRIO) at 10.0/storage/xtradb/include/sync0sync.ic:399
#7  0x0000000000bb6f69 in log_write_up_to (lsn=3655998, wait=92, flush_to_disk=1) at 10.0/storage/xtradb/log/log0log.cc:1575
#8  0x0000000000cc8896 in trx_flush_log_if_needed_low (lsn=3655998, trx=0x7fe9874cce78) at 10.0/storage/xtradb/trx/trx0trx.cc:1312
#9  0x0000000000cc8903 in trx_flush_log_if_needed (lsn=3655998, trx=0x7fe9874cce78) at 10.0/storage/xtradb/trx/trx0trx.cc:1336
#10 0x0000000000cc9022 in trx_commit_in_memory (trx=0x7fe9874cce78, lsn=3655998) at 10.0/storage/xtradb/trx/trx0trx.cc:1479
#11 0x0000000000cc962c in trx_commit_low (trx=0x7fe9874cce78, mtr=0x7fe9b54fdfb0) at 10.0/storage/xtradb/trx/trx0trx.cc:1591
#12 0x0000000000cc96b8 in trx_commit (trx=0x7fe9874cce78) at 10.0/storage/xtradb/trx/trx0trx.cc:1612
#13 0x0000000000cc9ec7 in trx_commit_for_mysql (trx=0x7fe9874cce78) at 10.0/storage/xtradb/trx/trx0trx.cc:1840
#14 0x0000000000d6dc58 in dict_stats_exec_sql (pinfo=0x7fe98770caf8, sql=0x119dfe8 "PROCEDURE INDEX_STATS_SAVE_INSERT () IS\nBEGIN\nINSERT INTO \"mysql/innodb_index_stats\"\nVALUES\n(\n:database_name,\n:table_name,\n:index_name,\n:last_update,\n:stat_name,\n:stat_value,\n:sample_size,\n:stat_descr"...) at 10.0/storage/xtradb/dict/dict0stats.cc:301
#15 0x0000000000d710e7 in dict_stats_save_index_stat (index=0x7fe987583570, last_update=1395007430, stat_name=0x7fe9b54fec80 "n_diff_pfx01", stat_value=0, sample_size=0x7fe9875837c0, stat_description=0x7fe9b54fee30 "col_datetime_not_null_key") at 10.0/storage/xtradb/dict/dict0stats.cc:2148
#16 0x0000000000d718a1 in dict_stats_save (table_orig=0x7fe9877093f8) at 10.0/storage/xtradb/dict/dict0stats.cc:2358
#17 0x0000000000d72bd7 in dict_stats_update (table=0x7fe9877093f8, stats_upd_option=DICT_STATS_EMPTY_TABLE) at 10.0/storage/xtradb/dict/dict0stats.cc:2991
#18 0x0000000000b59a2d in ha_innobase::create (this=0x7fe9875d9088, name=0x7fe9b54ffd40 "./test/table0_innodb_key_pk_parts_2_timestamp_6#P#p1", form=0x7fe9b5500220, create_info=0x7fe9b5502d20) at 10.0/storage/xtradb/handler/ha_innodb.cc:10561
#19 0x000000000084e162 in handler::ha_create (this=0x7fe9875d9088, name=0x7fe9b54ffd40 "./test/table0_innodb_key_pk_parts_2_timestamp_6#P#p1", form=0x7fe9b5500220, info=0x7fe9b5502d20) at 10.0/sql/handler.cc:4244
#20 0x0000000000ea2925 in ha_partition::create (this=0x7fe9874ee088, name=0x7fe9b5502730 "./test/table0_innodb_key_pk_parts_2_timestamp_6", table_arg=0x7fe9b5500220, create_info=0x7fe9b5502d20) at 10.0/sql/ha_partition.cc:733
#21 0x000000000084e162 in handler::ha_create (this=0x7fe9874ee088, name=0x7fe9b5502730 "./test/table0_innodb_key_pk_parts_2_timestamp_6", form=0x7fe9b5500220, info=0x7fe9b5502d20) at 10.0/sql/handler.cc:4244
#22 0x000000000084f046 in ha_create_table (thd=0x7fe98ee93070, path=0x7fe9b5502730 "./test/table0_innodb_key_pk_parts_2_timestamp_6", db=0x7fe98744dad8 "test", table_name=0x7fe98744d428 "table0_innodb_key_pk_parts_2_timestamp_6", create_info=0x7fe9b5502d20, frm=0x7fe9b5502720) at 10.0/sql/handler.cc:4613
#23 0x0000000000744e49 in rea_create_table (thd=0x7fe98ee93070, frm=0x7fe9b5502720, path=0x7fe9b5502730 "./test/table0_innodb_key_pk_parts_2_timestamp_6", db=0x7fe98744dad8 "test", table_name=0x7fe98744d428 "table0_innodb_key_pk_parts_2_timestamp_6", create_info=0x7fe9b5502d20, file=0x7fe987601418, no_ha_create_table=false) at 10.0/sql/unireg.cc:409
#24 0x00000000006ff192 in create_table_impl (thd=0x7fe98ee93070, db=0x7fe98744dad8 "test", table_name=0x7fe98744d428 "table0_innodb_key_pk_parts_2_timestamp_6", path=0x7fe9b5502730 "./test/table0_innodb_key_pk_parts_2_timestamp_6", create_info=0x7fe9b5502d20, alter_info=0x7fe9b5502c90, create_table_mode=0, is_trans=0x7fe9b5502992, key_info=0x7fe9b5502710, key_count=0x7fe9b5502704, frm=0x7fe9b5502720) at 10.0/sql/sql_table.cc:4706
#25 0x00000000006ff6d7 in mysql_create_table_no_lock (thd=0x7fe98ee93070, db=0x7fe98744dad8 "test", table_name=0x7fe98744d428 "table0_innodb_key_pk_parts_2_timestamp_6", create_info=0x7fe9b5502d20, alter_info=0x7fe9b5502c90, is_trans=0x7fe9b5502992, create_table_mode=0) at 10.0/sql/sql_table.cc:4817
#26 0x00000000006ff8cc in mysql_create_table (thd=0x7fe98ee93070, create_table=0x7fe98744d500, create_info=0x7fe9b5502d20, alter_info=0x7fe9b5502c90) at 10.0/sql/sql_table.cc:4870
#27 0x000000000064dfa8 in mysql_execute_command (thd=0x7fe98ee93070) at 10.0/sql/sql_parse.cc:3055
#28 0x000000000065742c in mysql_parse (thd=0x7fe98ee93070, rawbuf=0x7fe98744c088 "CREATE TABLE `table0_innodb_key_pk_parts_2_timestamp_6` (\n`col_time_not_null_key` time not null,\n`col_time_3` time(3),\n`col_time_6_not_null_key` time(6) not null,\n`col_time_3_not_null` time(3) not nul"..., length=2429, parser_state=0x7fe9b55035c0) at 10.0/sql/sql_parse.cc:6447
#29 0x0000000000649f23 in dispatch_command (command=COM_QUERY, thd=0x7fe98ee93070, packet=0x7fe98ee99071 "CREATE TABLE `table0_innodb_key_pk_parts_2_timestamp_6` (\n`col_time_not_null_key` time not null,\n`col_time_3` time(3),\n`col_time_6_not_null_key` time(6) not null,\n`col_time_3_not_null` time(3) not nul"..., packet_length=2429) at 10.0/sql/sql_parse.cc:1308
#30 0x000000000064927d in do_command (thd=0x7fe98ee93070) at 10.0/sql/sql_parse.cc:1005
#31 0x000000000076ebdb in do_handle_one_connection (thd_arg=0x7fe98ee93070) at 10.0/sql/sql_connect.cc:1379
#32 0x000000000076e941 in handle_one_connection (arg=0x7fe98ee93070) at 10.0/sql/sql_connect.cc:1293
#33 0x0000000000e8adf6 in pfs_spawn_thread (arg=0x7fe994fd9ef0) at 10.0/storage/perfschema/pfs.cc:1853
#34 0x00007fe9b47c3e9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#35 0x00007fe9b3cdacbd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#36 0x0000000000000000 in ?? ()

revision-id: psergey@askmonty.org-20140314175216-ztbe8wskbc5ou7vn
date: 2014-03-14 18:52:16 +0100
build-date: 2014-03-17 01:00:16 +0200
revno: 4054
branch-nick: 10.0

More stack traces are attached.

Gliffy Diagrams

Attachments

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

Attachments

threads1
29 kB
2014-03-17 01:28
threads2
32 kB
2014-03-17 01:28
threads3
28 kB
2014-03-17 01:28

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Jan Lindström added a comment - 2014-03-18 16:11

Debug build only, thus marking as minor. Related to https://mariadb.atlassian.net/browse/MDEV-5830.

Show

Jan Lindström added a comment - 2014-03-18 16:11 Debug build only, thus marking as minor. Related to https://mariadb.atlassian.net/browse/MDEV-5830 .

Hide

Permalink

Jan Lindström added a comment - 2014-03-21 10:58

After fix for https://mariadb.atlassian.net/browse/MDEV-5830 , can't repeat anymore.

Tested with n=0; while [[ $n -lt 30 ]]; do sh o.sh; n=$((n+1)); done on perro where o.sh is

perl ./runall-new.pl -~~grammar=conf/temporal/temporal_functions.yy --gendata=conf/temporal/temporal_functions.zz --duration=300 --threads=1 --queries=100M --basedir=/home/mariadb/mdev5830/10.0 --vardir=/dev/shm --mysqld=~~-innodb_priority_cleaner=ON --engine=InnoDB
{noformat]

Show

Jan Lindström added a comment - 2014-03-21 10:58 After fix for https://mariadb.atlassian.net/browse/MDEV-5830 , can't repeat anymore. Tested with n=0; while [[ $n -lt 30 ]]; do sh o.sh; n=$((n+1)); done on perro where o.sh is perl ./runall-new.pl - grammar=conf/temporal/temporal_functions.yy --gendata=conf/temporal/temporal_functions.zz --duration=300 --threads=1 --queries=100M --basedir=/home/mariadb/mdev5830/10.0 --vardir=/dev/shm --mysqld= -innodb_priority_cleaner=ON --engine=InnoDB {noformat]

Server hangs on single-threaded operation with XtraDB table with --innodb_priority_cleaner=ON

Details

Description

Gliffy Diagrams

Attachments

Attachments

Activity

People

Dates

Time Tracking

Agile