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

[Draft] Assertion `!rw_lock_own(btr_get_search_latch(index), RW_LOCK_X)' failed in btr_search_info_update

    XMLWordPrintable

Details

    Description

      10.3 70d6c944cbc1a7

      mysqld: /data/src/10.3/storage/innobase/include/btr0sea.ic:66: void btr_search_info_update(dict_index_t*, btr_cur_t*): Assertion `!rw_lock_own(btr_get_search_latch(index), RW_LOCK_X)' failed.
      171211 20:11:29 [ERROR] mysqld got signal 6 ;
       
      Server version: 10.3.3-MariaDB-debug-log
      key_buffer_size=134217728
      read_buffer_size=131072
      max_used_connections=8
      max_threads=153
      thread_count=14
      It is possible that mysqld could use up to 
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467412 K  bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.
       
      Thread pointer: 0x7fd09c000b00
      Attempting backtrace. You can use the following information to find out
      where mysqld died. If you see no messages after this, something went
      terribly wrong...
      stack_bottom = 0x7fd0fd74eec0 thread_stack 0x49000
      /data/bld/10.3/bin/mysqld(my_print_stacktrace+0x40)[0x56460f4bfe84]
      /data/bld/10.3/bin/mysqld(handle_fatal_signal+0x3a8)[0x56460ece1a9b]
      /lib/x86_64-linux-gnu/libpthread.so.0(+0x110c0)[0x7fd116c3c0c0]
      /lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7fd114f62fcf]
      /lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fd114f643fa]
      /lib/x86_64-linux-gnu/libc.so.6(+0x2be37)[0x7fd114f5be37]
      mysys/stacktrace.c:269(my_print_stacktrace)[0x7fd114f5bee2]
      include/btr0sea.ic:68(btr_search_info_update(dict_index_t*, btr_cur_t*))[0x56460f2803ef]
      btr/btr0cur.cc:2193(btr_cur_search_to_nth_level(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, unsigned long, char const*, unsigned int, mtr_t*, unsigned long))[0x56460f28666b]
      include/btr0pcur.ic:459(btr_pcur_open_low(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_pcur_t*, char const*, unsigned int, unsigned long, mtr_t*))[0x56460f19dbd0]
      row/row0row.cc:1115(row_search_index_entry(dict_index_t*, dtuple_t const*, unsigned long, btr_pcur_t*, mtr_t*))[0x56460f1a08e3]
      row/row0upd.cc:2392(row_upd_sec_index_entry(upd_node_t*, que_thr_t*))[0x56460f1d5455]
      row/row0upd.cc:2549(row_upd_sec_step(upd_node_t*, que_thr_t*))[0x56460f1d5dce]
      row/row0upd.cc:3306(row_upd(upd_node_t*, que_thr_t*))[0x56460f1d85b2]
      row/row0upd.cc:3421(row_upd_step(que_thr_t*))[0x56460f1d8920]
      row/row0mysql.cc:1976(row_update_for_mysql(row_prebuilt_t*))[0x56460f173116]
      handler/ha_innodb.cc:9140(ha_innobase::update_row(unsigned char const*, unsigned char const*))[0x56460f018aaa]
      sql/handler.cc:6098(handler::ha_update_row(unsigned char const*, unsigned char const*))[0x56460ecf1fe3]
      sql/sql_update.cc:884(mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, enum_duplicates, bool, unsigned long long*, unsigned long long*))[0x56460eb0c08f]
      sql/sql_parse.cc:4555(mysql_execute_command(THD*))[0x56460ea1d1cf]
      sql/sql_parse.cc:7959(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x56460ea27ede]
      sql/sql_parse.cc:1830(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x56460ea1581a]
      sql/sql_parse.cc:1370(do_command(THD*))[0x56460ea1423b]
      sql/sql_connect.cc:1420(do_handle_one_connection(CONNECT*))[0x56460eb6cb9c]
      sql/sql_connect.cc:1327(handle_one_connection)[0x56460eb6c929]
      /lib/x86_64-linux-gnu/libpthread.so.0(+0x7494)[0x7fd116c32494]
      /lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fd11501893f]
       
      Trying to get some variables.
      Some pointers may be invalid and cause the dump to abort.
      Query (0x7fd09c0158c8): UPDATE table11_innodb SET `col_int_key` = 3 /* QNO 28041 CON_ID 14 */
      Connection ID (thread ID): 14
      Status: NOT_KILLED
      

      #7  0x00007fd114f5bee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      #8  0x000056460f2803ef in btr_search_info_update (index=0x7fd09c40de58, cursor=0x7fd0fd74c2b0) at /data/src/10.3/storage/innobase/include/btr0sea.ic:66
      #9  0x000056460f28666b in btr_cur_search_to_nth_level (index=0x7fd09c40de58, level=0, tuple=0x7fd09c1f2878, mode=PAGE_CUR_LE, latch_mode=2, cursor=0x7fd0fd74c2b0, has_search_latch=0, file=0x56460f7d72f0 "/data/src/10.3/storage/innobase/row/row0row.cc", line=1115, mtr=0x7fd0fd74c7d0, autoinc=0) at /data/src/10.3/storage/innobase/btr/btr0cur.cc:2190
      #10 0x000056460f19dbd0 in btr_pcur_open_low (index=0x7fd09c40de58, level=0, tuple=0x7fd09c1f2878, mode=PAGE_CUR_LE, latch_mode=2, cursor=0x7fd0fd74c2b0, file=0x56460f7d72f0 "/data/src/10.3/storage/innobase/row/row0row.cc", line=1115, autoinc=0, mtr=0x7fd0fd74c7d0) at /data/src/10.3/storage/innobase/include/btr0pcur.ic:459
      #11 0x000056460f1a08e3 in row_search_index_entry (index=0x7fd09c40de58, entry=0x7fd09c1f2878, mode=2, pcur=0x7fd0fd74c2b0, mtr=0x7fd0fd74c7d0) at /data/src/10.3/storage/innobase/row/row0row.cc:1115
      #12 0x000056460f1d5455 in row_upd_sec_index_entry (node=0x7fd09c09d3f8, thr=0x7fd09c09d728) at /data/src/10.3/storage/innobase/row/row0upd.cc:2392
      #13 0x000056460f1d5dce in row_upd_sec_step (node=0x7fd09c09d3f8, thr=0x7fd09c09d728) at /data/src/10.3/storage/innobase/row/row0upd.cc:2549
      #14 0x000056460f1d85b2 in row_upd (node=0x7fd09c09d3f8, thr=0x7fd09c09d728) at /data/src/10.3/storage/innobase/row/row0upd.cc:3306
      #15 0x000056460f1d8920 in row_upd_step (thr=0x7fd09c09d728) at /data/src/10.3/storage/innobase/row/row0upd.cc:3421
      #16 0x000056460f173116 in row_update_for_mysql (prebuilt=0x7fd09c09cc18) at /data/src/10.3/storage/innobase/row/row0mysql.cc:1974
      #17 0x000056460f018aaa in ha_innobase::update_row (this=0x7fd09c2ccd48, old_row=0x7fd09c118318 <incomplete sequence \371>, new_row=0x7fd09c118308 "\371\003") at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:9140
      #18 0x000056460ecf1fe3 in handler::ha_update_row (this=0x7fd09c2ccd48, old_data=0x7fd09c118318 <incomplete sequence \371>, new_data=0x7fd09c118308 "\371\003") at /data/src/10.3/sql/handler.cc:6098
      #19 0x000056460eb0c08f in mysql_update (thd=0x7fd09c000b00, table_list=0x7fd09c015a10, fields=..., values=..., conds=0x0, order_num=0, order=0x0, limit=18446744073709551612, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7fd0fd74d7b0, updated_return=0x7fd0fd74d860) at /data/src/10.3/sql/sql_update.cc:884
      #20 0x000056460ea1d1cf in mysql_execute_command (thd=0x7fd09c000b00) at /data/src/10.3/sql/sql_parse.cc:4555
      #21 0x000056460ea27ede in mysql_parse (thd=0x7fd09c000b00, rawbuf=0x7fd09c0158c8 "UPDATE table11_innodb SET `col_int_key` = 3 /* QNO 28041 CON_ID 14 */", length=69, parser_state=0x7fd0fd74e660, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7959
      #22 0x000056460ea1581a in dispatch_command (command=COM_QUERY, thd=0x7fd09c000b00, packet=0x7fd09c00af41 " UPDATE table11_innodb SET `col_int_key` = 3 /* QNO 28041 CON_ID 14 */ ", packet_length=71, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1828
      #23 0x000056460ea1423b in do_command (thd=0x7fd09c000b00) at /data/src/10.3/sql/sql_parse.cc:1370
      #24 0x000056460eb6cb9c in do_handle_one_connection (connect=0x564612808d60) at /data/src/10.3/sql/sql_connect.cc:1420
      #25 0x000056460eb6c929 in handle_one_connection (arg=0x564612808d60) at /data/src/10.3/sql/sql_connect.cc:1326
      #26 0x00007fd116c32494 in start_thread (arg=0x7fd0fd74f700) at pthread_create.c:333
      #27 0x00007fd11501893f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      All threads' stack trace from the assertion failure is attached as assertion_failure_threads.

      It happened upon a concurrent test. Not easily reproducible.

      perl ./run-scenario.pl --grammar=conf/runtime/metadata_stability.yy --gendata=conf/runtime/metadata_stability.zz --duration=400 --threads=6 --queries=100M --redefine=conf/mariadb/instant_add.yy --mysqld=--max-statement-time=30 --reporters=Backtrace,ErrorLog,Deadlock --scenario=Restart --engine=InnoDB --mysqld=--innodb_stats_persistent=0 --seed=1512966342 --basedir=/data/bld/10.3 --vardir=/dev/shm/vardir1
      

      General log is attached.


      While trying to reproduce it, I got a hang instead.

      2017-12-11 21:11:21 19 [Note] InnoDB: Deleting the meta-data file './test/t14.cfg'
      2017-12-11 21:11:21 19 [Note] InnoDB: Resuming purge
      2017-12-11 21:15:24 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710695130880 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:24 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140711278212864 has waited at ha_innodb.cc line 5937 for 241.00 seconds the semaphore:
      Mutex at 0x55e4d3621290, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
      Last time reserved in file /data/src/10.3/storage/innobase/row/row0mysql.cc line 2364
      2017-12-11 21:15:24 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710703523584 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:24 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710711916288 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:24 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140711278515968 has waited at btr0sea.ic line 114 for 241.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d309e340 created in file btr0sea.cc line 260
      a writer (thread id 140711279425280) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-12-11 21:15:24 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710923409152 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:24 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710931801856 has waited at srv0srv.cc line 2120 for 240.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:24 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710695130880 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:24 0 [Note] InnoDB: A semaphore wait:
      --Thread 140711278212864 has waited at ha_innodb.cc line 5937 for 241.00 seconds the semaphore:
      Mutex at 0x55e4d3621290, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
      Last time reserved in file /data/src/10.3/storage/innobase/row/row0mysql.cc line 2364
      2017-12-11 21:15:24 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710703523584 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:24 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710711916288 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:24 0 [Note] InnoDB: A semaphore wait:
      --Thread 140711278515968 has waited at btr0sea.ic line 114 for 241.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d309e340 created in file btr0sea.cc line 260
      a writer (thread id 140711279425280) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-12-11 21:15:24 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710923409152 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0
       
      =====================================
      2017-12-11 21:15:30 0x7ff9d29b5700 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 35 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 45 srv_active, 0 srv_shutdown, 49 srv_idle
      srv_master_thread log flush and writes: 93
      ----------
      SEMAPHORES
      ----------
      -------------
      RW-LATCH INFO
      -------------
      RW-LOCK: 0x55e4d36211d0  (1 waiters)
      Locked: thread 140711278515968 file handler0alter.cc line 9172  X-LOCK
      RW-LOCK: 0x55e4d309e340  (1 waiters)
      Locked: thread 140711279425280 file btr0sea.ic line 96  X-LOCK
      RW-LOCK: 0x55e4d309e180 
      Locked: thread 140711278515968 file btr0sea.ic line 114  X-LOCK
      RW-LOCK: 0x55e4d309dfc0 
      Locked: thread 140711278515968 file btr0sea.ic line 114  X-LOCK
      RW-LOCK: 0x55e4d309de00 
      Locked: thread 140711278515968 file btr0sea.ic line 114  X-LOCK
      RW-LOCK: 0x55e4d309dc40 
      Locked: thread 140711278515968 file btr0sea.ic line 114  X-LOCK
      RW-LOCK: 0x55e4d309da80 
      Locked: thread 140711278515968 file btr0sea.ic line 114  X-LOCK
      Total number of rw-locks 16551
      OS WAIT ARRAY INFO: reservation count 21868
      --Thread 140710931801856 has waited at srv0srv.cc line 2120 for 246.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      --Thread 140710695130880 has waited at row0purge.cc line 928 for 247.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      --Thread 140711278212864 has waited at ha_innodb.cc line 5937 for 247.00 seconds the semaphore:
      Mutex at 0x55e4d3621290, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
      Last time reserved in file /data/src/10.3/storage/innobase/row/row0mysql.cc line 2364
      --Thread 140710703523584 has waited at row0purge.cc line 928 for 247.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      --Thread 140710711916288 has waited at row0purge.cc line 928 for 247.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      --Thread 140711278515968 has waited at btr0sea.ic line 114 for 247.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d309e340 created in file btr0sea.cc line 260
      a writer (thread id 140711279425280) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      --Thread 140710923409152 has waited at row0purge.cc line 928 for 247.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      OS WAIT ARRAY INFO: signal count 16163
      RW-shared spins 0, rounds 29983, OS waits 10368
      RW-excl spins 0, rounds 97931, OS waits 2555
      RW-sx spins 4, rounds 76, OS waits 0
      Spin rounds per wait: 29983.00 RW-shared, 97931.00 RW-excl, 19.00 RW-sx
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 21649
      Purge done for trx's n:o < 21648 undo n:o < 0 state: running
      History list length 25
      Total number of lock structs in row lock hash table 0
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 422186629261816, not started
      0 lock struct(s), heap size 1160, 0 row lock(s)
      ---TRANSACTION 422186629260744, not started
      0 lock struct(s), heap size 1160, 0 row lock(s)
      ---TRANSACTION 422186629258600, not started
      0 lock struct(s), heap size 1160, 0 row lock(s)
      ---TRANSACTION 422186629259672, not started
      mysql tables in use 1, locked 1
      0 lock struct(s), heap size 1160, 0 row lock(s)
      ---TRANSACTION 422186629257528, not started
      mysql tables in use 1, locked 1
      0 lock struct(s), heap size 1160, 0 row lock(s)
      ---TRANSACTION 422186629256456, not started
      0 lock struct(s), heap size 1160, 0 row lock(s)
      ---TRANSACTION 422186629255384, not started
      0 lock struct(s), heap size 1160, 0 row lock(s)
      --------
      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 (read thread)
      I/O thread 5 state: waiting for completed aio requests (read thread)
      I/O thread 6 state: waiting for completed aio requests (write thread)
      I/O thread 7 state: waiting for completed aio requests (write thread)
      I/O thread 8 state: waiting for completed aio requests (write thread)
      I/O thread 9 state: waiting for completed aio requests (write thread)
      Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
       ibuf aio reads:, log i/o's:, sync i/o's:
      Pending flushes (fsync) log: 0; buffer pool: 0
      180 OS file reads, 20815 OS file writes, 13662 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, 0 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
      2017-12-11 21:15:55 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710931801856 has waited at srv0srv.cc line 2120 for 271.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710695130880 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140711278212864 has waited at ha_innodb.cc line 5937 for 272.00 seconds the semaphore:
      Mutex at 0x55e4d3621290, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
      Last time reserved in file /data/src/10.3/storage/innobase/row/row0mysql.cc line 2364
      2017-12-11 21:15:55 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710703523584 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710711916288 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140711278515968 has waited at btr0sea.ic line 114 for 272.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d309e340 created in file btr0sea.cc line 260
      a writer (thread id 140711279425280) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-12-11 21:15:55 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710923409152 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710931801856 has waited at srv0srv.cc line 2120 for 271.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710956979968 has waited at srv0srv.cc line 1306 for 25.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d309da80 created in file btr0sea.cc line 260
      a writer (thread id 140711278515968) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 114
      2017-12-11 21:15:55 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710695130880 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Note] InnoDB: A semaphore wait:
      --Thread 140711278212864 has waited at ha_innodb.cc line 5937 for 272.00 seconds the semaphore:
      Mutex at 0x55e4d3621290, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
      Last time reserved in file /data/src/10.3/storage/innobase/row/row0mysql.cc line 2364
      2017-12-11 21:15:55 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710703523584 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710711916288 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:15:55 0 [Note] InnoDB: A semaphore wait:
      --Thread 140711278515968 has waited at btr0sea.ic line 114 for 272.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d309e340 created in file btr0sea.cc line 260
      a writer (thread id 140711279425280) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-12-11 21:15:55 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710923409152 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0
      InnoDB: ###### Diagnostic info printed to the standard error stream
      2017-12-11 21:16:26 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710931801856 has waited at srv0srv.cc line 2120 for 302.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710695130880 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140711278212864 has waited at ha_innodb.cc line 5937 for 303.00 seconds the semaphore:
      Mutex at 0x55e4d3621290, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
      Last time reserved in file /data/src/10.3/storage/innobase/row/row0mysql.cc line 2364
      2017-12-11 21:16:26 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710703523584 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710711916288 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140711278515968 has waited at btr0sea.ic line 114 for 303.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d309e340 created in file btr0sea.cc line 260
      a writer (thread id 140711279425280) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-12-11 21:16:26 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140710923409152 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710931801856 has waited at srv0srv.cc line 2120 for 302.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710956979968 has waited at srv0srv.cc line 1306 for 56.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d309da80 created in file btr0sea.cc line 260
      a writer (thread id 140711278515968) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 114
      2017-12-11 21:16:26 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710695130880 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Note] InnoDB: A semaphore wait:
      --Thread 140711278212864 has waited at ha_innodb.cc line 5937 for 303.00 seconds the semaphore:
      Mutex at 0x55e4d3621290, Mutex DICT_SYS created dict0dict.cc:1098, lock var 2
      Last time reserved in file /data/src/10.3/storage/innobase/row/row0mysql.cc line 2364
      2017-12-11 21:16:26 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710703523584 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710711916288 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      2017-12-11 21:16:26 0 [Note] InnoDB: A semaphore wait:
      --Thread 140711278515968 has waited at btr0sea.ic line 114 for 303.00 seconds the semaphore:
      X-lock on RW-latch at 0x55e4d309e340 created in file btr0sea.cc line 260
      a writer (thread id 140711279425280) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-12-11 21:16:26 0 [Note] InnoDB: A semaphore wait:
      --Thread 140710923409152 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55e4d36211d0 created in file dict0dict.cc line 1109
      a writer (thread id 140711278515968) 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 928
      Last time write locked in file handler0alter.cc line 9172
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0
      InnoDB: ###### Diagnostic info printed to the standard error stream
      

      It started complaining about long semaphore wait as above, but then it stopped and just kept hanging.

      Thread 4 (Thread 0x7ff9e5c59700 (LWP 1122)):
      #0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
      #1  0x000055e4d099513a in os_event::wait (this=0x55e4d309e400) at /data/src/10.3/storage/innobase/os/os0event.cc:166
      #2  0x000055e4d0994b49 in os_event::wait_low (this=0x55e4d309e400, reset_sig_count=2) at /data/src/10.3/storage/innobase/os/os0event.cc:336
      #3  0x000055e4d0994eef in os_event_wait_low (event=0x55e4d309e400, reset_sig_count=2) at /data/src/10.3/storage/innobase/os/os0event.cc:535
      #4  0x000055e4d0aa5b08 in sync_array_wait_event (arr=0x55e4d2975530, cell=@0x7ff9e5c54788: 0x55e4d2975840) at /data/src/10.3/storage/innobase/sync/sync0arr.cc:475
      #5  0x000055e4d0aa92dd in rw_lock_x_lock_func (lock=0x55e4d309e340, pass=0, file_name=0x55e4d10e66c8 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=114) at /data/src/10.3/stora
      ge/innobase/sync/sync0rw.cc:767
      #6  0x000055e4d0b4eb5e in pfs_rw_lock_x_lock_func (lock=0x55e4d309e340, pass=0, file_name=0x55e4d10e66c8 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=114) at /data/src/10.3/s
      torage/innobase/include/sync0rw.ic:573
      #7  0x000055e4d0b52b9e in btr_search_x_lock_all () at /data/src/10.3/storage/innobase/include/btr0sea.ic:114
      #8  0x000055e4d0b539be in btr_search_enable () at /data/src/10.3/storage/innobase/btr/btr0sea.cc:438
      #9  0x000055e4d0908226 in ha_innobase::commit_inplace_alter_table (this=0x7ff97014a5a8, altered_table=0x7ff97012be90, ha_alter_info=0x7ff9e5c55570, commit=true) at /data/src/10.3/storage/innobase/handler/handler0alter.cc:9564
      #10 0x000055e4d059b3da in handler::ha_commit_inplace_alter_table (this=0x7ff97014a5a8, altered_table=0x7ff97012be90, ha_alter_info=0x7ff9e5c55570, commit=true) at /data/src/10.3/sql/handler.cc:4251
      #11 0x000055e4d039ac98 in mysql_inplace_alter_table (thd=0x7ff970000b00, table_list=0x7ff970029ed0, table=0x7ff9701293d0, altered_table=0x7ff97012be90, ha_alter_info=0x7ff9e5c55570, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7ff9e5c555e0, alter_ctx=0x7ff9e5c561a0) at /data/src/10.3/sql/sql_table.cc:7261
      #12 0x000055e4d039ff7c in mysql_alter_table (thd=0x7ff970000b00, new_db=0x7ff97002a4e0 "test", new_name=0x0, create_info=0x7ff9e5c56db0, table_list=0x7ff970029ed0, alter_info=0x7ff9e5c56d00, order_num=0, order=0x0, ignore=false) at /data/src/10.3/sql/sql_table.cc:9237
      #13 0x000055e4d0420023 in Sql_cmd_alter_table::execute (this=0x7ff97002a738, thd=0x7ff970000b00) at /data/src/10.3/sql/sql_alter.cc:331
      #14 0x000055e4d02d14da in mysql_execute_command (thd=0x7ff970000b00) at /data/src/10.3/sql/sql_parse.cc:6245
      #15 0x000055e4d02d5ede in mysql_parse (thd=0x7ff970000b00, rawbuf=0x7ff970029d48 "ALTER TABLE t20 ADD COLUMN IF NOT EXISTS vcol7 DATE AS ( tcol4 ) VIRTUAL, LOCK=SHARED /* QNO 11141 CON_ID 17 */", length=111, parser_state=0x7ff9e5c58660, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7959
      #16 0x000055e4d02c381a in dispatch_command (command=COM_QUERY, thd=0x7ff970000b00, packet=0x7ff97000b041 "ALTER TABLE t20 ADD COLUMN IF NOT EXISTS vcol7 DATE AS ( tcol4 ) VIRTUAL, LOCK=SHARED /* QNO 11141 CON_ID 17 */", packet_length=111, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1828
      #17 0x000055e4d02c223b in do_command (thd=0x7ff970000b00) at /data/src/10.3/sql/sql_parse.cc:1370
      #18 0x000055e4d041ab9c in do_handle_one_connection (connect=0x55e4d3370e60) at /data/src/10.3/sql/sql_connect.cc:1420
      #19 0x000055e4d041a929 in handle_one_connection (arg=0x55e4d3370e60) at /data/src/10.3/sql/sql_connect.cc:1326
      #20 0x00007ff9ff17d494 in start_thread (arg=0x7ff9e5c59700) at pthread_create.c:333
      #21 0x00007ff9fd56393f in clone () from /lib/x86_64-linux-gnu/libc.so.6
       
      Thread 3 (Thread 0x7ff9e5c0f700 (LWP 1123)):
      #0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
      #1  0x000055e4d099513a in os_event::wait (this=0x55e4d36213a0) at /data/src/10.3/storage/innobase/os/os0event.cc:166
      #2  0x000055e4d0994b49 in os_event::wait_low (this=0x55e4d36213a0, reset_sig_count=3533) at /data/src/10.3/storage/innobase/os/os0event.cc:336
      #3  0x000055e4d0994eef in os_event_wait_low (event=0x55e4d36213a0, reset_sig_count=3533) at /data/src/10.3/storage/innobase/os/os0event.cc:535
      #4  0x000055e4d0aa5b08 in sync_array_wait_event (arr=0x55e4d2975530, cell=@0x7ff9e5c0a960: 0x55e4d2975740) at /data/src/10.3/storage/innobase/sync/sync0arr.cc:475
      #5  0x000055e4d08e5862 in TTASEventMutex<GenericPolicy>::enter (this=0x55e4d3621290, max_spins=60, max_delay=6, filename=0x55e4d0ffd110 "/data/src/10.3/storage/innobase/handler/ha_innodb.cc", line=5937) at /data/src/10.3/storage/innobase/include/ib0mutex.h:516
      #6  0x000055e4d08e3e4b in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x55e4d3621290, n_spins=30, n_delay=6, name=0x55e4d0ffd110 "/data/src/10.3/storage/innobase/handler/ha_innodb.cc", line=5937) at /data/src/10.3/storage/innobase/include/ib0mutex.h:635
      #7  0x000055e4d08bebfa in innobase_build_index_translation (table=0x7ff97411c040, ib_table=0x7ff9740c2fd8, share=0x7ff9740fb610) at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:5937
      #8  0x000055e4d08bfc94 in ha_innobase::open (this=0x7ff9740ba078, name=0x7ff9740cc508 "./test/t17") at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:6388
      #9  0x000055e4d05962fa in handler::ha_open (this=0x7ff9740ba078, table_arg=0x7ff97411c040, name=0x7ff9740cc508 "./test/t17", mode=2, test_if_locked=18, mem_root=0x0) at /data/src/10.3/sql/handler.cc:2515
      #10 0x000055e4d03d1d0e in open_table_from_share (thd=0x7ff974000b00, share=0x7ff9740cbfe8, alias=0x7ff974029e78 "t17", db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7ff97411c040, is_create_table=false) at /data/src/10.3/sql/table.cc:3339
      #11 0x000055e4d024621b in open_table (thd=0x7ff974000b00, table_list=0x7ff974029e80, ot_ctx=0x7ff9e5c0b400) at /data/src/10.3/sql/sql_base.cc:1907
      #12 0x000055e4d039add2 in mysql_inplace_alter_table (thd=0x7ff974000b00, table_list=0x7ff974029e80, table=0x0, altered_table=0x7ff97411c040, ha_alter_info=0x7ff9e5c0b570, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7ff9e5c0b5e0, alter_ctx=0x7ff9e5c0c1a0) at /data/src/10.3/sql/sql_table.cc:7293
      #13 0x000055e4d039ff7c in mysql_alter_table (thd=0x7ff974000b00, new_db=0x7ff97402a490 "test", new_name=0x0, create_info=0x7ff9e5c0cdb0, table_list=0x7ff974029e80, alter_info=0x7ff9e5c0cd00, order_num=0, order=0x0, ignore=false) at /data/src/10.3/sql/sql_table.cc:9237
      #14 0x000055e4d0420023 in Sql_cmd_alter_table::execute (this=0x7ff97402a4a0, thd=0x7ff974000b00) at /data/src/10.3/sql/sql_alter.cc:331
      #15 0x000055e4d02d14da in mysql_execute_command (thd=0x7ff974000b00) at /data/src/10.3/sql/sql_parse.cc:6245
      #16 0x000055e4d02d5ede in mysql_parse (thd=0x7ff974000b00, rawbuf=0x7ff974029d48 "ALTER TABLE t17 FORCE, ALGORITHM=INPLACE /* QNO 11620 CON_ID 18 */", length=66, parser_state=0x7ff9e5c0e660, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7959
      #17 0x000055e4d02c381a in dispatch_command (command=COM_QUERY, thd=0x7ff974000b00, packet=0x7ff97400b041 "ALTER TABLE t17 FORCE, ALGORITHM=INPLACE /* QNO 11620 CON_ID 18 */", packet_length=66, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1828
      #18 0x000055e4d02c223b in do_command (thd=0x7ff974000b00) at /data/src/10.3/sql/sql_parse.cc:1370
      #19 0x000055e4d041ab9c in do_handle_one_connection (connect=0x55e4d3370e60) at /data/src/10.3/sql/sql_connect.cc:1420
      #20 0x000055e4d041a929 in handle_one_connection (arg=0x55e4d3370e60) at /data/src/10.3/sql/sql_connect.cc:1326
      #21 0x00007ff9ff17d494 in start_thread (arg=0x7ff9e5c0f700) at pthread_create.c:333
      #22 0x00007ff9fd56393f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      All threads' stack trace from the hang is attached as hang_threads.

      It happened upon running a huge (automatically generated) MTR test, on 2nd repetition. The test is attached.

      perl ./mtr bug.latch1 --default-server --mysqld=--sql-mode= --mysqld=--max-statement-time=30 --mysqld=--innodb_stats_persistent=0 --mem --testcase-timeout=300 --mysqld=--lock-wait-timeout=5 --mysqld=--innodb-lock-wait-timeout=3 --repeat=5
      

      Not easily reproducible.

      Attachments

        1. assertion_failure_threads
          55 kB
        2. assertion_failure_threads_full
          188 kB
        3. hang_threads
          54 kB
        4. hang_threads_full
          156 kB
        5. latch1.test.gz
          1.41 MB
        6. mysql.log.gz
          1.33 MB

        Issue Links

          Activity

            People

              elenst Elena Stepanova
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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