Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-12754

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

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 10.2
    • Fix Version/s: 10.2.6
    • Component/s: Tests
    • Labels:
      None

      Description

      http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/8062/steps/test_1/logs/stdio

      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
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              serg Sergei Golubchik
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: