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

Parallel slave: slave hangs on ALTER TABLE (or other DDL) as the first event after slave start

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 10.1
    • Fix Version/s: 10.1.5
    • Component/s: Replication
    • Labels:
      None

      Description

      Note: 10.0 might also be affected, I encountered the problem on 10.1 because that's where tests were running.

      Stack trace from 10.1 commit 539b3ca87

      Thread 6 (Thread 0x7fb11fc80700 (LWP 19403)):
      #0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
      #1  0x00007fb122e5d626 in safe_cond_wait (cond=0x7fb0f5c538e8, mp=0x7fb0f5c53838, file=0x7fb122f13120 "10.1/include/mysql/psi/mysql_thread.h", line=1165) at 10.1/mysys/thr_mutex.c:493
      #2  0x00007fb12259a66b in inline_mysql_cond_wait (that=0x7fb0f5c538e8, mutex=0x7fb0f5c53838, src_file=0x7fb122f13988 "10.1/sql/sql_class.cc", src_line=6853) at 10.1/include/mysql/psi/mysql_thread.h:1165
      #3  0x00007fb1225aad83 in wait_for_commit::wait_for_prior_commit2 (this=0x7fb0f5c53838, thd=0x7fb10c96e070) at 10.1/sql/sql_class.cc:6853
      #4  0x00007fb12258a451 in wait_for_commit::wait_for_prior_commit (this=0x7fb0f5c53838, thd=0x7fb10c96e070) at 10.1/sql/sql_class.h:1780
      #5  0x00007fb12258a760 in THD::wait_for_prior_commit (this=0x7fb10c96e070) at 10.1/sql/sql_class.h:3781
      #6  0x00007fb12281077f in ha_commit_one_phase (thd=0x7fb10c96e070, all=true) at 10.1/sql/handler.cc:1536
      #7  0x00007fb12281009d in ha_commit_trans (thd=0x7fb10c96e070, all=true) at 10.1/sql/handler.cc:1406
      #8  0x00007fb122720121 in trans_commit (thd=0x7fb10c96e070) at 10.1/sql/transaction.cc:236
      #9  0x00007fb1225e6650 in mysql_execute_command (thd=0x7fb10c96e070) at 10.1/sql/sql_parse.cc:4864
      #10 0x00007fb1225ecfaa in mysql_parse (thd=0x7fb10c96e070, rawbuf=0x7fb0f5d0ab79 "COMMIT", length=6, parser_state=0x7fb11fc7fa60) at 10.1/sql/sql_parse.cc:7165
      #11 0x00007fb122902c8c in Query_log_event::do_apply_event (this=0x7fb0f5d18670, rgi=0x7fb0f5c53800, query_arg=0x7fb0f5d0ab79 "COMMIT", q_len_arg=6) at 10.1/sql/log_event.cc:4287
      #12 0x00007fb122901f11 in Query_log_event::do_apply_event (this=0x7fb0f5d18670, rgi=0x7fb0f5c53800) at 10.1/sql/log_event.cc:4013
      #13 0x00007fb12254a5da in Log_event::apply_event (this=0x7fb0f5d18670, rgi=0x7fb0f5c53800) at 10.1/sql/log_event.h:1347
      #14 0x00007fb12254014f in apply_event_and_update_pos (ev=0x7fb0f5d18670, thd=0x7fb10c96e070, rgi=0x7fb0f5c53800, rpt=0x7fb0f5e221b0) at 10.1/sql/slave.cc:3274
      #15 0x00007fb122777043 in rpt_handle_event (qev=0x7fb0f5d47970, rpt=0x7fb0f5e221b0) at 10.1/sql/rpl_parallel.cc:49
      #16 0x00007fb1227792ec in handle_rpl_parallel_thread (arg=0x7fb0f5e221b0) at 10.1/sql/rpl_parallel.cc:942
      #17 0x00007fb121cc7b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
      #18 0x00007fb11fd5c95d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #19 0x0000000000000000 in ?? ()
       
      Thread 5 (Thread 0x7fb11ebb5700 (LWP 19404)):
      #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:216
      #1  0x00007fb122e5d92d in safe_cond_timedwait (cond=0x7fb11e65b218, mp=0x7fb11e65b168, abstime=0x7fb11ebb1a70, file=0x7fb122f69680 "10.1/include/mysql/psi/mysql_thread.h", line=1202) at 10.1/mysys/thr_mutex.c:547
      #2  0x00007fb1227153d9 in inline_mysql_cond_timedwait (that=0x7fb11e65b218, mutex=0x7fb11e65b168, abstime=0x7fb11ebb1a70, src_file=0x7fb122f698e8 "10.1/sql/mdl.cc", src_line=1066) at 10.1/include/mysql/psi/mysql_thread.h:1202
      #3  0x00007fb122716549 in MDL_wait::timed_wait (this=0x7fb11e65b168, owner=0x7fb11e65b120, abs_timeout=0x7fb11ebb1a70, set_status_on_timeout=false, wait_state_name=0x7fb12370a8b0) at 10.1/sql/mdl.cc:1066
      #4  0x00007fb122717f2d in MDL_context::acquire_lock (this=0x7fb11e65b168, mdl_request=0x7fb11ebb1b40, lock_wait_timeout=31536000) at 10.1/sql/mdl.cc:2039
      #5  0x00007fb1227186f2 in MDL_context::upgrade_shared_lock (this=0x7fb11e65b168, mdl_ticket=0x7fb11e44c0c0, new_type=MDL_EXCLUSIVE, lock_wait_timeout=31536000) at 10.1/sql/mdl.cc:2232
      #6  0x00007fb12257763d in wait_while_table_is_used (thd=0x7fb11e65b070, table=0x7fb0f55dce70, function=HA_EXTRA_PREPARE_FOR_RENAME) at 10.1/sql/sql_base.cc:1874
      #7  0x00007fb12269cbf7 in mysql_inplace_alter_table (thd=0x7fb11e65b070, table_list=0x7fb11e664128, table=0x7fb0f55dce70, altered_table=0x7fb11e656070, ha_alter_info=0x7fb11ebb1f80, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7fb11ebb1ff0, alter_ctx=0x7fb11ebb2b80) at 10.1/sql/sql_table.cc:7036
      #8  0x00007fb1226a147c in mysql_alter_table (thd=0x7fb11e65b070, new_db=0x7fb11e664708 "test", new_name=0x0, create_info=0x7fb11ebb3780, table_list=0x7fb11e664128, alter_info=0x7fb11ebb36f0, order_num=0, order=0x0, ignore=false) at 10.1/sql/sql_table.cc:8821
      #9  0x00007fb122710ecd in Sql_cmd_alter_table::execute (this=0x7fb11e6648a8, thd=0x7fb11e65b070) at 10.1/sql/sql_alter.cc:325
      #10 0x00007fb1225e8c79 in mysql_execute_command (thd=0x7fb11e65b070) at 10.1/sql/sql_parse.cc:5558
      #11 0x00007fb1225ecfaa in mysql_parse (thd=0x7fb11e65b070, rawbuf=0x7fb0f5d041b9 "ALTER TABLE table10_innodb ADD COLUMN `default` INTEGER DEFAULT 5", length=65, parser_state=0x7fb11ebb4a60) at 10.1/sql/sql_parse.cc:7165
      #12 0x00007fb122902c8c in Query_log_event::do_apply_event (this=0x7fb0f5d15e30, rgi=0x7fb0f5c53000, query_arg=0x7fb0f5d041b9 "ALTER TABLE table10_innodb ADD COLUMN `default` INTEGER DEFAULT 5", q_len_arg=65) at 10.1/sql/log_event.cc:4287
      #13 0x00007fb122901f11 in Query_log_event::do_apply_event (this=0x7fb0f5d15e30, rgi=0x7fb0f5c53000) at 10.1/sql/log_event.cc:4013
      #14 0x00007fb12254a5da in Log_event::apply_event (this=0x7fb0f5d15e30, rgi=0x7fb0f5c53000) at 10.1/sql/log_event.h:1347
      #15 0x00007fb12254014f in apply_event_and_update_pos (ev=0x7fb0f5d15e30, thd=0x7fb11e65b070, rgi=0x7fb0f5c53000, rpt=0x7fb0f5e22380) at 10.1/sql/slave.cc:3274
      #16 0x00007fb122777043 in rpt_handle_event (qev=0x7fb0f5d46a70, rpt=0x7fb0f5e22380) at 10.1/sql/rpl_parallel.cc:49
      #17 0x00007fb1227792ec in handle_rpl_parallel_thread (arg=0x7fb0f5e22380) at 10.1/sql/rpl_parallel.cc:942
      #18 0x00007fb121cc7b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
      #19 0x00007fb11fd5c95d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #20 0x0000000000000000 in ?? ()
       
      Thread 2 (Thread 0x7fb0fd7f5700 (LWP 19439)):
      #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:216
      #1  0x00007fb122e5d92d in safe_cond_timedwait (cond=0x7fb10d88adf8, mp=0x7fb10d88ad10, abstime=0x7fb0fd7f3490, file=0x7fb122eff5a0 "10.1/include/mysql/psi/mysql_thread.h", line=1202) at 10.1/mysys/thr_mutex.c:547
      #2  0x00007fb122536c6c in inline_mysql_cond_timedwait (that=0x7fb10d88adf8, mutex=0x7fb10d88ad10, abstime=0x7fb0fd7f3490, src_file=0x7fb122effcb0 "10.1/sql/slave.cc", src_line=791) at 10.1/include/mysql/psi/mysql_thread.h:1202
      #3  0x00007fb12253880d in terminate_slave_thread (thd=0x7fb0f5d64070, term_lock=0x7fb10d88ad10, term_cond=0x7fb10d88adf8, slave_running=0x7fb10d88b7ec, skip_lock=true) at 10.1/sql/slave.cc:791
      #4  0x00007fb1225381af in terminate_slave_threads (mi=0x7fb10d887000, thread_mask=3, skip_lock=true) at 10.1/sql/slave.cc:636
      #5  0x00007fb12261425e in stop_slave (thd=0x7fb0fcaa2070, mi=0x7fb10d887000, net_report=true) at 10.1/sql/sql_repl.cc:3186
      #6  0x00007fb1225e1658 in mysql_execute_command (thd=0x7fb0fcaa2070) at 10.1/sql/sql_parse.cc:3530
      #7  0x00007fb1225ecfaa in mysql_parse (thd=0x7fb0fcaa2070, rawbuf=0x7fb0f3a97088 "STOP SLAVE SQL_THREAD, IO_THREAD", length=32, parser_state=0x7fb0fd7f4200) at 10.1/sql/sql_parse.cc:7165
      #8  0x00007fb1225dbfba in dispatch_command (command=COM_QUERY, thd=0x7fb0fcaa2070, packet=0x7fb102b48071 "STOP SLAVE SQL_THREAD, IO_THREAD", packet_length=32) at 10.1/sql/sql_parse.cc:1462
      #9  0x00007fb1225dad8a in do_command (thd=0x7fb0fcaa2070) at 10.1/sql/sql_parse.cc:1090
      #10 0x00007fb12270c1df in do_handle_one_connection (thd_arg=0x7fb0fcaa2070) at 10.1/sql/sql_connect.cc:1347
      #11 0x00007fb12270bf24 in handle_one_connection (arg=0x7fb0fcaa2070) at 10.1/sql/sql_connect.cc:1258
      #12 0x00007fb121cc7b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
      #13 0x00007fb11fd5c95d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      #14 0x0000000000000000 in ?? ()

      All threads' stack traces are attached (threads1 and threads1_full).

      Processlist

      +-----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+-------------------------------------------------------------------+----------+
      | Id  | User        | Host            | db   | Command | Time   | State                                                                          | Info                                                              | Progress |
      +-----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+-------------------------------------------------------------------+----------+
      |  25 | root        | localhost:41433 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  26 | root        | localhost:41435 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  27 | root        | localhost:41437 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  28 | root        | localhost:41439 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  29 | root        | localhost:41441 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  30 | root        | localhost:41443 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  31 | root        | localhost:41445 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  32 | root        | localhost:41447 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  33 | root        | localhost:41449 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  34 | root        | localhost:41451 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  35 | root        | localhost:41453 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  36 | root        | localhost:41455 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  37 | root        | localhost:41457 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  38 | root        | localhost:41459 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  39 | root        | localhost:41461 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  40 | root        | localhost:41463 | NULL | Query   | 124675 | init                                                                           | SHOW SLAVE STATUS                                                 |    0.000 |
      |  98 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      |  99 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 100 | system user |                 | test | Connect | 124749 | Waiting for prior transaction to commit                                        | COMMIT                                                            |    0.000 |
      | 101 | system user |                 | test | Connect | 124750 | Waiting for prior transaction to commit                                        | COMMIT                                                            |    0.000 |
      | 102 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 103 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 104 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 105 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to commit                                        | NULL                                                              |    0.000 |
      | 106 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 107 | system user |                 | test | Connect | 124749 | Waiting for prior transaction to commit                                        | COMMIT                                                            |    0.000 |
      | 108 | system user |                 | test | Connect | 124749 | Waiting for prior transaction to commit                                        | COMMIT                                                            |    0.000 |
      | 109 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 110 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 111 | system user |                 | test | Connect | 124750 | Waiting for prior transaction to commit                                        | COMMIT                                                            |    0.000 |
      | 112 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 113 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 114 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 115 | system user |                 | NULL | Connect | 124726 | Waiting for prior transaction to start commit before starting next transaction | NULL                                                              |    0.000 |
      | 116 | system user |                 | NULL | Connect | 124750 | Waiting for prior transaction to commit                                        | NULL                                                              |    0.000 |
      | 117 | system user |                 | test | Connect | 124756 | Waiting for table metadata lock                                                | ALTER TABLE table10_innodb ADD COLUMN `default` INTEGER DEFAULT 5 |    0.000 |
      | 118 | system user |                 | NULL | Connect | 124690 | Reading event from the relay log                                               | NULL                                                              |    0.000 |
      | 127 | system user |                 | NULL | Connect | 124690 | Waiting for master to send event                                               | NULL                                                              |    0.000 |
      | 130 | root        | localhost:41537 | NULL | Query   | 124675 | Killing slave                                                                  | STOP SLAVE SQL_THREAD, IO_THREAD                                  |    0.000 |
      | 134 | root        | localhost:52917 | test | Query   |      0 | init                                                                           | show processlist                                                  |    0.000 |
      +-----+-------------+-----------------+------+---------+--------+--------------------------------------------------------------------------------+-------------------------------------------------------------------+----------+

      Slave command line

      /home/elenst/git/10.1/sql/mysqld --no-defaults --basedir=/home/elenst/git/10.1 --datadir=/home/elenst/test_results/analyze6_slave/data --lc-messages-dir=/home/elenst/git/10.1/sql/share --character-sets-dir=/home/elenst/git/10.1/sql/share/charsets --tmpdir=/home/elenst/test_results/analyze6_slave/tmp --core-file --max-allowed-packet=128Mb --port=10722 --socket=/home/elenst/test_results/analyze6_slave/mysql.sock --pid-file=/home/elenst/test_results/analyze6_slave/mysql.pid --general-log --general-log-file=/home/elenst/test_results/analyze6_slave/mysql.log --server_id=2 --report-host=127.0.0.1 --report_port=10722 --log_bin_trust_function_creators=1 --slave-skip-errors=1054,1317,1049,1305,1539,1505 --slave-parallel-mode=optimistic --binlog_commit_wait_count=20 --binlog_commit_wait_usec=1000000 --slave-parallel-threads=20 --innodb --sql-mode=no_engine_substitution

      SHOW SLAVE STATUS hangs.

      gtid_slave_pos

      +------------------+
      | @@gtid_slave_pos |
      +------------------+
      | 0-1-846          |
      +------------------+

      Master's binlog is attached (mysql-bin.*).
      Slave is running without binary logging.
      Master's general log is attached (master.log).
      Slave's general and error logs are attached (slave.log, slave.err).

        Attachments

        1. master.log
          442 kB
        2. mysql-bin.000001
          243 kB
        3. mysql-bin.index
          0.0 kB
        4. slave.err
          7 kB
        5. slave.log
          179 kB
        6. threads1
          88 kB
        7. threads1_full
          296 kB

          Activity

            People

            Assignee:
            knielsen Kristian Nielsen
            Reporter:
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: