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

innodb.truncate_debug 'innodb'           w2 [ fail ]

        Test ended at 2017-05-08 21:58:39

CURRENT_TEST: innodb.truncate_debug

Warning: /mnt/buildbot/build/mariadb-10.2.6/libmysqld/examples/mysqltest_embedded: unknown variable 'loose-ssl-ca=/mnt/buildbot/build/mariadb-10.2.6/mysql-test/std_data/cacert.pem'

Warning: /mnt/buildbot/build/mariadb-10.2.6/libmysqld/examples/mysqltest_embedded: unknown variable 'loose-ssl-cert=/mnt/buildbot/build/mariadb-10.2.6/mysql-test/std_data/client-cert.pem'

Warning: /mnt/buildbot/build/mariadb-10.2.6/libmysqld/examples/mysqltest_embedded: unknown variable 'loose-ssl-key=/mnt/buildbot/build/mariadb-10.2.6/mysql-test/std_data/client-key.pem'

Warning: /mnt/buildbot/build/mariadb-10.2.6/libmysqld/examples/mysqltest_embedded: unknown option '--loose-skip-ssl'

--Thread 2845211456 has waited at btr0sea.ic line 114 for 241.00 seconds the semaphore:

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

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

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

Last time read locked in file btr0sea.ic line 152

Last time write locked in file not yet reserved line 0

--Thread 2845211456 has waited at btr0sea.ic line 114 for 241.00 seconds the semaphore:

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

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

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

Last time read locked in file btr0sea.ic line 152

Last time write locked in file not yet reserved line 0

--Thread 2963266368 has waited at srv0srv.cc line 2175 for 240.00 seconds the semaphore:

Mutex at 0xb9003d8, Mutex DICT_SYS created dict0dict.cc:1101, lock var 2

Last time reserved in file /home/buildbot/buildbot/build/mariadb-10.2.6/storage/innobase/btr/btr0sea.cc line 313

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

InnoDB: Pending reads 0, writes 0

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

2017-05-08 21:57:45 0xb11feb40 INNODB MONITOR OUTPUT

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

Per second averages calculated from the last 16 seconds

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

BACKGROUND THREAD

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

srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 9 srv_idle

srv_master_thread log flush and writes: 10

----------

SEMAPHORES

----------

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

RW-LATCH INFO

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

RW-LOCK: 0xb6016758 

Locked: thread 2845510464 file dict0dict.ic line 1138  X-LOCK

RW-LOCK: 0xb6009d78 

Locked: thread 2845510464 file dict0dict.ic line 1138  X-LOCK

RW-LOCK: 0xb6009518 

Locked: thread 2845510464 file dict0dict.ic line 1138  X-LOCK

RW-LOCK: 0xb900368 

Locked: thread 2963266368 file srv0srv.cc line 2173  X-LOCK

RW-LOCK: 0xb88ae78 

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

RW-LOCK: 0xb88ad48 

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

RW-LOCK: 0xb88ac18 

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

RW-LOCK: 0xb88aae8 

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

RW-LOCK: 0xb88a9b8 

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

RW-LOCK: 0xb88a888 

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

RW-LOCK: 0xb88a758 

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

RW-LOCK: 0xb88a628 

Locked: thread 2845211456 file btr0sea.ic line 114  WAIT X-LOCK

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

Total number of rw-locks 1084

OS WAIT ARRAY INFO: reservation count 165

--Thread 2845211456 has waited at btr0sea.ic line 114 for 250.00 seconds the semaphore:

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

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

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

Last time read locked in file btr0sea.ic line 152

Last time write locked in file not yet reserved line 0

--Thread 2963266368 has waited at srv0srv.cc line 2175 for 249.00 seconds the semaphore:

Mutex at 0xb9003d8, Mutex DICT_SYS created dict0dict.cc:1101, lock var 2

Last time reserved in file /home/buildbot/buildbot/build/mariadb-10.2.6/storage/innobase/btr/btr0sea.cc line 313

OS WAIT ARRAY INFO: signal count 117

RW-shared spins 0, rounds 21, OS waits 9

RW-excl spins 0, rounds 34, OS waits 5

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

Spin rounds per wait: 21.00 RW-shared, 34.00 RW-excl, 0.00 RW-sx

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

TRANSACTIONS

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

Trx id counter 1341

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

History list length 7

Total number of lock structs in row lock hash table 0

LIST OF TRANSACTIONS FOR EACH SESSION:

---TRANSACTION 18446744072480630052, not started

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

---TRANSACTION 1319, ACTIVE 260 sec truncating table

mysql tables in use 1, locked 1

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

MySQL thread id 7, OS thread handle 0x0, query id 2845510464 localhost root debug sync point: buffer_pool_scan

truncate table t1

--------

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

190 OS file reads, 287 OS file writes, 63 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

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

--Thread 2845211456 has waited at btr0sea.ic line 114 for 272.00 seconds the semaphore:

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

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

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

Last time read locked in file btr0sea.ic line 152

Last time write locked in file not yet reserved line 0

--Thread 2963266368 has waited at srv0srv.cc line 2175 for 271.00 seconds the semaphore:

Mutex at 0xb9003d8, Mutex DICT_SYS created dict0dict.cc:1101, lock var 2

Last time reserved in file /home/buildbot/buildbot/build/mariadb-10.2.6/storage/innobase/btr/btr0sea.cc line 313

--Thread 2845211456 has waited at btr0sea.ic line 114 for 272.00 seconds the semaphore:

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

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

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

Last time read locked in file btr0sea.ic line 152

Last time write locked in file not yet reserved line 0

--Thread 2963266368 has waited at srv0srv.cc line 2175 for 271.00 seconds the semaphore:

Mutex at 0xb9003d8, Mutex DICT_SYS created dict0dict.cc:1101, lock var 2

Last time reserved in file /home/buildbot/buildbot/build/mariadb-10.2.6/storage/innobase/btr/btr0sea.cc line 313

--Thread 2971659072 has waited at srv0srv.cc line 1367 for 22.00 seconds the semaphore:

S-lock on RW-latch at 0xb88a628 created in file btr0sea.cc line 193

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

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

Last time read locked in file btr0sea.ic line 152

Last time write locked in file not yet reserved line 0

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

InnoDB: Pending reads 0, writes 0

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

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

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

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

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

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

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

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

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

---

LOG

---

Log sequence number 1689903

Log flushed up to   1689409

Pages flushed up to 1689409

Last checkpoint at  1689233

0 pending log flushes, 0 pending chkp writes

43 log i/o's done, 0.04 log i/o's/second

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

BUFFER POOL AND MEMORY

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

Total large memory allocated 8634368

Dictionary memory allocated 56639

Buffer pool size   511

Free buffers       164

Database pages     347

Old database pages 0

Modified db pages  2

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

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 0

0.00 youngs/s, 0.00 non-youngs/s

Pages read 174, created 184, written 230

0.00 reads/s, 0.05 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: 347, 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=11083, Main thread ID=2963266368, state: sleeping

Number of rows inserted 63, updated 0, deleted 0, read 66

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

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

--- /mnt/buildbot/build/mariadb-10.2.6/mysql-test/suite/innodb/r/truncate_debug.result	2017-05-08 19:10:08.000000000 +0300

+++ /mnt/buildbot/build/mariadb-10.2.6/mysql-test/suite/innodb/r/truncate_debug.reject	2017-05-08 21:58:26.000000000 +0300

@@ -77,6 +77,8 @@

 SET DEBUG_SYNC= 'now SIGNAL finish_scan';

 SET DEBUG_SYNC= 'RESET';

 connection con1;

+Warnings:

+Warning	1639	debug sync point wait timed out

 disconnect con1;

 connection con2;

 disconnect con2;

mysqltest: Result length mismatch

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

2017-05-08 21:58:26 0xb11feb40 INNODB MONITOR OUTPUT

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

Per second averages calculated from the last 41 seconds

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

BACKGROUND THREAD

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

srv_master_thread loops: 2 srv_active, 0 srv_shutdown, 9 srv_idle

srv_master_thread log flush and writes: 11

----------

SEMAPHORES

----------

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

RW-LATCH INFO

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

Total number of rw-locks 1070

OS WAIT ARRAY INFO: reservation count 178

OS WAIT ARRAY INFO: signal count 127

RW-shared spins 0, rounds 40, OS waits 18

RW-excl spins 0, rounds 128, OS waits 9

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

Spin rounds per wait: 40.00 RW-shared, 128.00 RW-excl, 0.00 RW-sx

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

TRANSACTIONS

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

Trx id counter 1354

Purge done for trx's n:o < 1354 undo n:o < 0 state: exited

History list length 0

Total number of lock structs in row lock hash table 0

LIST OF TRANSACTIONS FOR EACH SESSION:

--------

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

190 OS file reads, 297 OS file writes, 73 OS fsyncs

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

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

INSERT BUFFER AND ADAPTIVE HASH INDEX

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

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

merged operations:

 insert 0, delete mark 0, delete 0

discarded operations:

 insert 0, delete mark 0, delete 0

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

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

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

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

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

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

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

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

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

---

LOG

---

Log sequence number 1703290

Log flushed up to   1702639

Pages flushed up to 1689903

Last checkpoint at  1689233

0 pending log flushes, 0 pending chkp writes

50 log i/o's done, 7.00 log i/o's/second

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

BUFFER POOL AND MEMORY

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

Total large memory allocated 8634368

Dictionary memory allocated 39367

Buffer pool size   511

Free buffers       157

Database pages     354

Old database pages 0

Modified db pages  33

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

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 0

0.00 youngs/s, 0.00 non-youngs/s

Pages read 174, created 191, written 230

0.00 reads/s, 6.99 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: 354, 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=11083, Main thread ID=2963266368, state: sleeping

Number of rows inserted 63, updated 0, deleted 0, read 66

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

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

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