[MDEV-13256] innodb.truncate_debug fails in buildbot - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.3
Fix Version/s: 10.2.10, 10.3.2
Component/s: Storage Engine - InnoDB, Tests
Labels:
None

Description

Note: the report was initially filed for 10.2, but it appears that the failure on 10.2 has gone away, while on 10.3 it is still happening, so the item has been updated to deal with 10.3 instead.

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/9240/steps/test_2/logs/stdio

innodb.truncate_debug 'innodb'           w1 [ fail ]

        Test ended at 2017-08-17 11:01:39

CURRENT_TEST: innodb.truncate_debug

--- /mnt/buildbot/build/mariadb-10.3.1/mysql-test/suite/innodb/r/truncate_debug.result	2017-08-17 09:13:54.000000000 +0300

+++ /mnt/buildbot/build/mariadb-10.3.1/mysql-test/suite/innodb/r/truncate_debug.reject	2017-08-17 11:01:38.000000000 +0300

@@ -76,6 +76,8 @@

 connection default;

 SET DEBUG_SYNC= 'now SIGNAL finish_scan';

 connection con1;

+Warnings:

+Warning	1639	debug sync point wait timed out

 disconnect con1;

 connection con2;

 disconnect con2;

mysqltest: Result length mismatch

The failure is reproducible locally quite well by running the test sequence which leads to it in buildbot; it can be reduced to these four tests:

perl ./mtr --noreorder --mem compat/oracle.sp-anonymous innodb.innodb-ucs2 innodb.tmpdir innodb.truncate_debug

It doesn't happen every time, but happens for me probably 4 times out of 5.
I couldn't remove any other test from the chain, but they can be put together and further reduced to the test that I will put at the end of the description. It also shows which part is taken from which test. Basically, before innodb.truncate_debug it is just a bunch of CREATE/DROP tables.

Both the sequence of tests and the hybrid test exhibit the same behavior. innodb.truncate_debug doesn't in fact hang on reap in connection con1; it hangs earlier, on truncate table t2 in connection default. I assume it gets somehow blocked by truncate table t1, which in turn is waiting on the sync point which is not sent, because connection default does not reach that point. After debug sync point timeout is exceeded, truncate table t1 gives up, which allows truncate table t2 to proceed and finish successfully, so all we get at the end if the misleading debug sync point wait timed out diagnostics.

Here is what the processlist looks like while the test is waiting:

+----+-------------+-----------------+------+---------+------+------------------------------------+-------------------+----------+

| Id | User        | Host            | db   | Command | Time | State                              | Info              | Progress |

+----+-------------+-----------------+------+---------+------+------------------------------------+-------------------+----------+

|  2 | system user |                 | NULL | Daemon  | NULL | InnoDB purge worker                | NULL              |    0.000 |

|  1 | system user |                 | NULL | Daemon  | NULL | InnoDB purge worker                | NULL              |    0.000 |

|  3 | system user |                 | NULL | Daemon  | NULL | InnoDB purge worker                | NULL              |    0.000 |

|  4 | system user |                 | NULL | Daemon  | NULL | InnoDB purge coordinator           | NULL              |    0.000 |

|  5 | system user |                 | NULL | Daemon  | NULL | InnoDB shutdown handler            | NULL              |    0.000 |

| 23 | root        | localhost       | test | Query   |  121 | NULL                               | truncate table t2 |    0.000 |

| 24 | root        | localhost       | test | Query   |  130 | debug sync point: buffer_pool_scan | truncate table t1 |    0.000 |

| 26 | root        | localhost:36340 | NULL | Query   |    0 | init                               | show processlist  |    0.000 |

+----+-------------+-----------------+------+---------+------+------------------------------------+-------------------+----------+

And here are the stack traces from these two threads:

Thread 3 (Thread 0x7fb6884dd700 (LWP 2540)):

#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185

#1  0x000055c0515ea9e2 in os_event::wait (this=0x55c0544651b0) at /data/src/10.3/storage/innobase/os/os0event.cc:166

#2  0x000055c0515ea3f1 in os_event::wait_low (this=0x55c0544651b0, reset_sig_count=2) at /data/src/10.3/storage/innobase/os/os0event.cc:336

#3  0x000055c0515ea797 in os_event_wait_low (event=0x55c0544651b0, reset_sig_count=2) at /data/src/10.3/storage/innobase/os/os0event.cc:535

#4  0x000055c051702d5c in sync_array_wait_event (arr=0x55c054273a80, cell=@0x7fb6884d9c88: 0x55c054273b50) at /data/src/10.3/storage/innobase/sync/sync0arr.cc:475

#5  0x000055c051705e36 in rw_lock_x_lock_wait_func (lock=0x55c054465060, pass=0, threshold=0, file_name=0x55c051cefa50 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=96) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:472

#6  0x000055c051705f9d in rw_lock_x_lock_low (lock=0x55c054465060, pass=0, file_name=0x55c051cefa50 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=96) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:536

#7  0x000055c0517063ff in rw_lock_x_lock_func (lock=0x55c054465060, pass=0, file_name=0x55c051cefa50 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=96) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:687

#8  0x000055c0517858fe in pfs_rw_lock_x_lock_func (lock=0x55c054465060, pass=0, file_name=0x55c051cefa50 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=96) at /data/src/10.3/storage/innobase/include/sync0rw.ic:539

#9  0x000055c05178de9f in btr_search_x_lock (index=0x55c054930e68) at /data/src/10.3/storage/innobase/include/btr0sea.ic:96

#10 0x000055c051798122 in btr_cur_update_in_place (flags=2, cursor=0x7fb63c0d4428, offsets=0x7fb6884da640, update=0x7fb63c0d45f8, cmpl_info=0, thr=0x7fb63c0d6858, trx_id=1863, mtr=0x7fb6884da960) at /data/src/10.3/storage/innobase/btr/btr0cur.cc:3706

#11 0x000055c0517989af in btr_cur_optimistic_update (flags=2, cursor=0x7fb63c0d4428, offsets=0x7fb6884da540, heap=0x7fb6884da5e8, update=0x7fb63c0d45f8, cmpl_info=0, thr=0x7fb63c0d6858, trx_id=1863, mtr=0x7fb6884da960) at /data/src/10.3/storage/innobase/btr/btr0cur.cc:3832

#12 0x000055c0516e150f in row_upd_clust_rec (flags=0, node=0x7fb63c0d3dd0, index=0x55c054930e68, offsets=0x7fb6884da640, offsets_heap=0x7fb6884da5e8, thr=0x7fb63c0d6858, mtr=0x7fb6884da960) at /data/src/10.3/storage/innobase/row/row0upd.cc:2845

#13 0x000055c0516e26e6 in row_upd_clust_step (node=0x7fb63c0d3dd0, thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/row/row0upd.cc:3211

#14 0x000055c0516e29a6 in row_upd (node=0x7fb63c0d3dd0, thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/row/row0upd.cc:3273

#15 0x000055c0516e2e9d in row_upd_step (thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/row/row0upd.cc:3417

#16 0x000055c051621779 in que_thr_step (thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/que/que0que.cc:1036

#17 0x000055c051621a81 in que_run_threads_low (thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/que/que0que.cc:1116

#18 0x000055c051621c63 in que_run_threads (thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/que/que0que.cc:1156

#19 0x000055c051621f04 in que_eval_sql (info=0x7fb63c0b3288, sql=0x55c051ca9330 "PROCEDURE RENUMBER_TABLE_ID_PROC () IS\nBEGIN\nUPDATE SYS_TABLES SET ID = :new_id\n WHERE ID = :old_id;\nUPDATE SYS_COLUMNS SET TABLE_ID = :new_id\n WHERE TABLE_ID = :old_id;\nUPDATE SYS_INDEXES SET TABLE_I"..., reserve_dict_mutex=0, trx=0x7fb688777878) at /data/src/10.3/storage/innobase/que/que0que.cc:1233

#20 0x000055c0516c48b5 in row_truncate_update_table_id (old_table_id=82, new_table_id=85, reserve_dict_mutex=0, trx=0x7fb688777878) at /data/src/10.3/storage/innobase/row/row0trunc.cc:1402

#21 0x000055c0516c4bda in row_truncate_update_system_tables (table=0x7fb63c033148, new_id=85, has_internal_doc_id=false, no_redo=true, trx=0x7fb688777878) at /data/src/10.3/storage/innobase/row/row0trunc.cc:1525

#22 0x000055c0516c5f9d in row_truncate_table_for_mysql (table=0x7fb63c033148, trx=0x7fb688777878) at /data/src/10.3/storage/innobase/row/row0trunc.cc:2086

#23 0x000055c05152b68d in ha_innobase::truncate (this=0x7fb63c0b37e8) at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:13374

#24 0x000055c051200b59 in handler::ha_truncate (this=0x7fb63c0b37e8) at /data/src/10.3/sql/handler.cc:4101

#25 0x000055c0513d3cdc in Sql_cmd_truncate_table::handler_truncate (this=0x7fb63c0150f0, thd=0x7fb63c000b00, table_ref=0x7fb63c014ad8, is_tmp_table=false) at /data/src/10.3/sql/sql_truncate.cc:246

#26 0x000055c0513d43a6 in Sql_cmd_truncate_table::truncate_table (this=0x7fb63c0150f0, thd=0x7fb63c000b00, table_ref=0x7fb63c014ad8) at /data/src/10.3/sql/sql_truncate.cc:445

#27 0x000055c0513d4518 in Sql_cmd_truncate_table::execute (this=0x7fb63c0150f0, thd=0x7fb63c000b00) at /data/src/10.3/sql/sql_truncate.cc:502

#28 0x000055c050f40233 in mysql_execute_command (thd=0x7fb63c000b00) at /data/src/10.3/sql/sql_parse.cc:6235

#29 0x000055c050f44b2a in mysql_parse (thd=0x7fb63c000b00, rawbuf=0x7fb63c014a08 "truncate table t2", length=17, parser_state=0x7fb6884dc610, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7921

#30 0x000055c050f32284 in dispatch_command (command=COM_QUERY, thd=0x7fb63c000b00, packet=0x7fb63c08f821 "truncate table t2", packet_length=17, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1819

#31 0x000055c050f30ce6 in do_command (thd=0x7fb63c000b00) at /data/src/10.3/sql/sql_parse.cc:1370

#32 0x000055c051087668 in do_handle_one_connection (connect=0x55c05479b000) at /data/src/10.3/sql/sql_connect.cc:1418

#33 0x000055c0510873f5 in handle_one_connection (arg=0x55c05479b000) at /data/src/10.3/sql/sql_connect.cc:1324

#34 0x000055c0514fee7a in pfs_spawn_thread (arg=0x55c0547a3940) at /data/src/10.3/storage/perfschema/pfs.cc:1862

#35 0x00007fb690790494 in start_thread (arg=0x7fb6884dd700) at pthread_create.c:333

#36 0x00007fb68e90893f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 2 (Thread 0x7fb688493700 (LWP 2559)):

#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225

#1  0x000055c0519cce91 in safe_cond_timedwait (cond=0x55c0525e81a0 <debug_sync_global+32>, mp=0x55c0525e81d8 <debug_sync_global+88>, abstime=0x7fb688490c60, file=0x55c051a64d40 "/data/src/10.3/include/mysql/psi/mysql_thread.h", line=1175) at /data/src/10.3/mysys/thr_mutex.c:546

#2  0x000055c050f6567f in inline_mysql_cond_timedwait (that=0x55c0525e81a0 <debug_sync_global+32>, mutex=0x55c0525e81d8 <debug_sync_global+88>, abstime=0x7fb688490c60, src_file=0x55c051a64e58 "/data/src/10.3/sql/debug_sync.cc", src_line=1444) at /data/src/10.3/include/mysql/psi/mysql_thread.h:1175

#3  0x000055c050f68726 in debug_sync_execute (thd=0x7fb628000b00, action=0x7fb628008090) at /data/src/10.3/sql/debug_sync.cc:1444

#4  0x000055c050f68d33 in debug_sync (thd=0x7fb628000b00, sync_point_name=0x55c051d3a378 "buffer_pool_scan", name_len=16) at /data/src/10.3/sql/debug_sync.cc:1552

#5  0x000055c05186344f in fil_reinit_space_header_for_table (table=0x7fb63c0b02f8, size=8, trx=0x7fb688777ca8) at /data/src/10.3/storage/innobase/fil/fil0fil.cc:3322

#6  0x000055c0516c5d36 in row_truncate_table_for_mysql (table=0x7fb63c0b02f8, trx=0x7fb688777ca8) at /data/src/10.3/storage/innobase/row/row0trunc.cc:2018

#7  0x000055c05152b68d in ha_innobase::truncate (this=0x7fb62801cf18) at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:13374

#8  0x000055c051200b59 in handler::ha_truncate (this=0x7fb62801cf18) at /data/src/10.3/sql/handler.cc:4101

#9  0x000055c0513d3cdc in Sql_cmd_truncate_table::handler_truncate (this=0x7fb628013d30, thd=0x7fb628000b00, table_ref=0x7fb628013718, is_tmp_table=false) at /data/src/10.3/sql/sql_truncate.cc:246

#10 0x000055c0513d43a6 in Sql_cmd_truncate_table::truncate_table (this=0x7fb628013d30, thd=0x7fb628000b00, table_ref=0x7fb628013718) at /data/src/10.3/sql/sql_truncate.cc:445

#11 0x000055c0513d4518 in Sql_cmd_truncate_table::execute (this=0x7fb628013d30, thd=0x7fb628000b00) at /data/src/10.3/sql/sql_truncate.cc:502

#12 0x000055c050f40233 in mysql_execute_command (thd=0x7fb628000b00) at /data/src/10.3/sql/sql_parse.cc:6235

#13 0x000055c050f44b2a in mysql_parse (thd=0x7fb628000b00, rawbuf=0x7fb628013648 "truncate table t1", length=17, parser_state=0x7fb688492610, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7921

#14 0x000055c050f32284 in dispatch_command (command=COM_QUERY, thd=0x7fb628000b00, packet=0x7fb62800af11 "truncate table t1", packet_length=17, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1819

#15 0x000055c050f30ce6 in do_command (thd=0x7fb628000b00) at /data/src/10.3/sql/sql_parse.cc:1370

#16 0x000055c051087668 in do_handle_one_connection (connect=0x55c05479b000) at /data/src/10.3/sql/sql_connect.cc:1418

#17 0x000055c0510873f5 in handle_one_connection (arg=0x55c05479b000) at /data/src/10.3/sql/sql_connect.cc:1324

#18 0x000055c0514fee7a in pfs_spawn_thread (arg=0x55c0547a3cf0) at /data/src/10.3/storage/perfschema/pfs.cc:1862

#19 0x00007fb690790494 in start_thread (arg=0x7fb688493700) at pthread_create.c:333

#20 0x00007fb68e90893f in clone () from /lib/x86_64-linux-gnu/libc.so.6

I can't get SHOW ENGINE INNODB STATUS because it is blocked too; but after 240 seconds it starts complaining about long semaphore wait, which leads to dumping the monitor information to the error log:

2017-09-25 16:31:18 0 [Warning] InnoDB: A long semaphore wait:

--Thread 140421947578112 has waited at btr0sea.ic line 96 for 241.00 seconds the semaphore:

X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193

a writer (thread id 140421947578112) has reserved it in mode  wait exclusive

number of readers 1, waiters flag 0, lock_word: ffffffffffffffff

Last time read locked in file btr0sea.ic line 152

Last time write locked in file btr0sea.ic line 96

2017-09-25 16:31:18 0 [Note] InnoDB: A semaphore wait:

--Thread 140421947578112 has waited at btr0sea.ic line 96 for 241.00 seconds the semaphore:

X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193

a writer (thread id 140421947578112) has reserved it in mode  wait exclusive

number of readers 1, waiters flag 0, lock_word: ffffffffffffffff

Last time read locked in file btr0sea.ic line 152

Last time write locked in file btr0sea.ic line 96

2017-09-25 16:31:18 0 [Note] InnoDB: A semaphore wait:

--Thread 140421690791680 has waited at srv0srv.cc line 2116 for 239.00 seconds the semaphore:

X-lock on RW-latch at 0x55c05492b5e0 created in file dict0dict.cc line 1112

a writer (thread id 140421947578112) has reserved it in mode  exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file row0purge.cc line 927

Last time write locked in file fil0fil.cc line 3326

InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:

InnoDB: Pending reads 0, writes 0

=====================================

2017-09-25 16:31:27 0x7fb67a7fc700 INNODB MONITOR OUTPUT

=====================================

Per second averages calculated from the last 16 seconds

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

BACKGROUND THREAD

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

srv_master_thread loops: 3 srv_active, 0 srv_shutdown, 9 srv_idle

srv_master_thread log flush and writes: 11

----------

SEMAPHORES

----------

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

RW-LATCH INFO

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

RW-LOCK: 0x55c05492b5e0  Waiters for the lock exist

Locked: thread 140421947578112 file fil0fil.cc line 3326  X-LOCK

RW-LOCK: 0x55c054465230

Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK

RW-LOCK: 0x55c054465060

Locked: thread 140421947578112 file btr0sea.ic line 96  WAIT X-LOCK

Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK

RW-LOCK: 0x55c054464e90

Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK

RW-LOCK: 0x55c054464cc0

Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK

RW-LOCK: 0x55c054464af0

Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK

RW-LOCK: 0x55c054464920

Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK

RW-LOCK: 0x55c054464750

Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK

RW-LOCK: 0x55c054464580

Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK

RW-LOCK: 0x7fb6837b6028

Locked: thread 140421947578112 file row0upd.cc line 3096  S-LOCK

RW-LOCK: 0x7fb6837b5ef8

Locked: thread 140421947578112 file row0upd.cc line 3096  X-LOCK

Total number of rw-locks 1085

OS WAIT ARRAY INFO: reservation count 250

--Thread 140421947578112 has waited at btr0sea.ic line 96 for 250.00 seconds the semaphore:

X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193

a writer (thread id 140421947578112) has reserved it in mode  wait exclusive

number of readers 1, waiters flag 0, lock_word: ffffffffffffffff

Last time read locked in file btr0sea.ic line 152

Last time write locked in file btr0sea.ic line 96

--Thread 140421690791680 has waited at srv0srv.cc line 2116 for 248.00 seconds the semaphore:

X-lock on RW-latch at 0x55c05492b5e0 created in file dict0dict.cc line 1112

a writer (thread id 140421947578112) has reserved it in mode  exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file row0purge.cc line 927

Last time write locked in file fil0fil.cc line 3326

OS WAIT ARRAY INFO: signal count 262

RW-shared spins 0, rounds 504, OS waits 89

RW-excl spins 0, rounds 1489, OS waits 8

RW-sx spins 0, rounds 0, OS waits 0

Spin rounds per wait: 504.00 RW-shared, 1489.00 RW-excl, 0.00 RW-sx

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

TRANSACTIONS

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

Trx id counter 1864

Purge done for trx's n:o < 1863 undo n:o < 0 state: running but idle

History list length 41

Total number of lock structs in row lock hash table 2

LIST OF TRANSACTIONS FOR EACH SESSION:

---TRANSACTION 1863, ACTIVE 250 sec truncating table

mysql tables in use 1, locked 1

3 lock struct(s), heap size 1160, 2 row lock(s), undo log entries 1

MySQL thread id 23, OS thread handle 0x7fb6884dd700, query id 552 localhost root

truncate table t2

---TRANSACTION 1860, ACTIVE 259 sec truncating table

mysql tables in use 1, locked 1

0 lock struct(s), heap size 1160, 0 row lock(s)

MySQL thread id 24, OS thread handle 0x7fb688493700, query id 537 localhost root debug sync point: buffer_pool_scan

truncate table t1

InnoDB: ###### Diagnostic info printed to the standard error stream

2017-09-25 16:31:49 0 [Warning] InnoDB: A long semaphore wait:

--Thread 140421947578112 has waited at btr0sea.ic line 96 for 272.00 seconds the semaphore:

X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193

a writer (thread id 140421947578112) has reserved it in mode  wait exclusive

number of readers 1, waiters flag 0, lock_word: ffffffffffffffff

Last time read locked in file btr0sea.ic line 152

Last time write locked in file btr0sea.ic line 96

2017-09-25 16:31:49 0 [Warning] InnoDB: A long semaphore wait:

--Thread 140421690791680 has waited at srv0srv.cc line 2116 for 270.00 seconds the semaphore:

X-lock on RW-latch at 0x55c05492b5e0 created in file dict0dict.cc line 1112

a writer (thread id 140421947578112) has reserved it in mode  exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file row0purge.cc line 927

Last time write locked in file fil0fil.cc line 3326

2017-09-25 16:31:49 0 [Note] InnoDB: A semaphore wait:

--Thread 140421947578112 has waited at btr0sea.ic line 96 for 272.00 seconds the semaphore:

X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193

a writer (thread id 140421947578112) has reserved it in mode  wait exclusive

number of readers 1, waiters flag 0, lock_word: ffffffffffffffff

Last time read locked in file btr0sea.ic line 152

Last time write locked in file btr0sea.ic line 96

2017-09-25 16:31:49 0 [Note] InnoDB: A semaphore wait:

--Thread 140421715969792 has waited at lock0lock.cc line 6573 for 22.00 seconds the semaphore:

X-lock on RW-latch at 0x7fb6837b5ef8 created in file buf0buf.cc line 1460

a writer (thread id 140421947578112) has reserved it in mode  exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file row0sel.cc line 915

Last time write locked in file row0upd.cc line 3096

2017-09-25 16:31:49 0 [Note] InnoDB: A semaphore wait:

--Thread 140421690791680 has waited at srv0srv.cc line 2116 for 270.00 seconds the semaphore:

X-lock on RW-latch at 0x55c05492b5e0 created in file dict0dict.cc line 1112

a writer (thread id 140421947578112) has reserved it in mode  exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file row0purge.cc line 927

Last time write locked in file fil0fil.cc line 3326

InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:

InnoDB: Pending reads 0, writes 0

--------

FILE I/O

--------

I/O thread 0 state: waiting for completed aio requests (insert buffer thread)

I/O thread 1 state: waiting for completed aio requests (log thread)

I/O thread 2 state: waiting for completed aio requests (read thread)

I/O thread 3 state: waiting for completed aio requests (read thread)

I/O thread 4 state: waiting for completed aio requests (write thread)

I/O thread 5 state: waiting for completed aio requests (write thread)

Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,

 ibuf aio reads:, log i/o's:, sync i/o's:

Pending flushes (fsync) log: 0; buffer pool: 0

292 OS file reads, 848 OS file writes, 459 OS fsyncs

0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s

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

INSERT BUFFER AND ADAPTIVE HASH INDEX

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

Ibuf: size 1, free list len 0, seg size 2, 3 merges

merged operations:

 insert 0, delete mark 0, delete 0

discarded operations:

 insert 0, delete mark 0, delete 0

Hash table size 2267, used cells 0, node heap has 0 buffer(s)

Hash table size 2267, used cells 0, node heap has 0 buffer(s)

Hash table size 2267, used cells 0, node heap has 0 buffer(s)

Hash table size 2267, used cells 0, node heap has 0 buffer(s)

Hash table size 2267, used cells 0, node heap has 0 buffer(s)

Hash table size 2267, used cells 0, node heap has 0 buffer(s)

Hash table size 2267, used cells 10, node heap has 1 buffer(s)

Hash table size 2267, used cells 0, node heap has 0 buffer(s)

0.00 hash searches/s, 0.31 non-hash searches/s

---

LOG

---

Log sequence number 2102801

Log flushed up to   2102648

Pages flushed up to 2102648

Last checkpoint at  2098486

0 pending log flushes, 0 pending chkp writes

295 log i/o's done, 0.00 log i/o's/second

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

BUFFER POOL AND MEMORY

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

Total large memory allocated 8814592

Dictionary memory allocated 95167

Buffer pool size   512

Free buffers       115

Database pages     396

Old database pages 0

Modified db pages  7

Percent of dirty pages(LRU & free pages): 1.367

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 0, not young 322

0.00 youngs/s, 0.00 non-youngs/s

Pages read 276, created 520, written 468

0.00 reads/s, 0.00 creates/s, 0.00 writes/s

Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 396, unzip_LRU len: 0

I/O sum[0]:cur[0], unzip sum[0]:cur[0]

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

ROW OPERATIONS

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

0 queries inside InnoDB, 0 queries in queue

0 read views open inside InnoDB

Process ID=2511, Main thread ID=140421690791680, state: making checkpoint

Number of rows inserted 199, updated 42, deleted 0, read 272

0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Number of system rows inserted 0, updated 0, deleted 0, read 0

0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

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

END OF INNODB MONITOR OUTPUT

============================

This is the essential part of the test sequence which leads to the same failure (with approximately the same frequency):

--source include/have_innodb.inc

--source include/have_debug_sync.inc

#########################################################

# sp-anonymous.test

CREATE TABLE t1 (a INT NOT NULL PRIMARY KEY) ENGINE=InnoDB;

DROP TABLE t1;

#########################################################

# innodb-ucs2.test

--disable_warnings

drop table if exists t1, t2;

--enable_warnings

create table t1 (

  a int, b text(10), c text(10), filler text(10), primary key(a, b(2)), unique key (a, c(2))

) character set utf8 engine = innodb;

drop table t1;

create table t1 (

  a int, b blob(10), c blob(10), filler blob(10), primary key(a, b(2)), unique key (a, c(2))

) character set utf8 engine = innodb;

create table t2 (

  a int, b blob(10), c blob(10), filler blob(10), primary key(a, b(2)), unique key (a, c(2))

) character set ucs2 engine = innodb;

drop table t1;

drop table t2;

commit;

create table t2 (

  a int, b char(10), filler char(10), primary key(a, b(2))

) character set utf8 engine = innodb;

drop table t2;

create table t2 (

  a int, b char(10), filler char(10), primary key(a, b(2))

) character set ucs2 engine = innodb;

drop table t2;

create table t1(a int not null, b char(110),primary key(a,b(100))) engine=innodb default charset=utf8;

drop table t1;

create table t1(a int not null, b text(110),primary key(a,b(100))) engine=innodb default charset=utf8;

drop table t1;

--echo End of 5.0 tests

#########################################################################

# innodb.tmpdir.test

create table t1(a int primary key)engine=innodb;

drop table t1;

create table t1(a text, b text, fulltext(a,b))engine=innodb;

insert into t1 values('test1', 'test2');

alter table t1 add fulltext(b);

drop table t1;

##############################################################

# innodb.truncate_debug.test

--source include/count_sessions.inc

create table t1 (f1 int,f2 int,key(f2),f3 int) engine=innodb;

create table t2 (f1 int,f2 int,key(f2),f3 int) engine=innodb;

SET session lock_wait_timeout = 1;

connect (con1,localhost,root,,);

SET DEBUG_SYNC= 'buffer_pool_scan SIGNAL started WAIT_FOR finish_scan';

send truncate table t1;

connection default;

SET DEBUG_SYNC= 'now WAIT_FOR started';

--echo Concurrent truncate on other tables

truncate table t2;

connection default;

SET DEBUG_SYNC= 'now SIGNAL finish_scan';

connection con1;

reap;

disconnect con1;

connection default;

SET DEBUG_SYNC= 'RESET';

SET session lock_wait_timeout=default;

drop table t1,t2;

--source include/wait_until_count_sessions.inc

Attachments

Issue Links

relates to

MDEV-12754 innodb.truncate_debug fails in buildbot with embedded due to semaphore wait

Closed

MDEV-15916 Change buffer crash during TRUNCATE or DROP TABLE

Closed

Activity

People

Assignee:: Marko Mäkelä

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2017-07-06 12:35

Updated:: 2018-04-18 16:51

Resolved:: 2017-10-11 09:15

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.