Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.3(EOL)
-
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
-
-
- Closed
-
-
-
- Closed
-