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

In a master-slave semi-synchronous instance, after the standby machine experiences a power outage and restarts, the master machine is unable to provide connection services for a period of time.

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Incomplete
    • 10.11.11
    • N/A
    • Replication
    • None

    Description

      I compared version 10.11.11 with version 10.5.16, and the bug only appears in the former. Below is a comparison of the two versions.

      This issue can only be reproduced under power-off conditions; it cannot occur through conventional methods such as killing the mysqld process or shutting down the environment.

      FInding 1. Applicable to 10.11 and 10.5
      The first step is to power off the standby machine while the main machine executes the SHOW FULL PROCESSLIST command. Both show:

      MariaDB [(none)]> show full processlist;
      		 
      +-------+----------+--------------------+------+-------------+------+---------------------------------------------------------------+-----------------------+----------+
      		 
      | Id    | User     | Host               | db   | Command     | Time | State                                                         | Info                  | Progress |
      		 
      +-------+----------+--------------------+------+-------------+------+---------------------------------------------------------------+-----------------------+----------+
      		 
      | 13976 | rdsRepl  | 172.16.58.41:36078 | NULL | Binlog Dump | 1228 | Master has sent all binlog to slave; waiting for more updates | NULL                  |    0.000 |
      		 
      | 15548 | rdsAdmin | localhost          | NULL | Query       |    0 | starting                                                      | show full processlist |    0.000 |
      		 
      +-------+----------+--------------------+------+-------------+------+---------------------------------------------------------------+-----------------------+----------+

      FInding 2. Applicable to 10.5
      When the standby machine and MySQL are started, the original Binlog Dump thread will be terminated, and a new thread will be created.

      MariaDB [(none)]> show full processlist;
      		 
      +---------+----------------------+---------------------+------+-------------+------+---------------------------------------------------------------+-----------------------+----------+
      		 
      | Id      | User                 | Host                | db   | Command     | Time | State                                                         | Info                  | Progress |
      		 
      +---------+----------------------+---------------------+------+-------------+------+---------------------------------------------------------------+-----------------------+----------+
      		 
      | 1578380 | rdsAdmin             | localhost           | NULL | Query       |    0 | starting                                                      | show full processlist |    0.000 |
      		 
      | 1578742 | rdsRepl              | 172.16.15.236:60038 | NULL | Binlog Dump |    4 | Master has sent all binlog to slave; waiting for more updates | NULL                  |    0.000 |
      		 
      | 1578747 | unauthenticated user | 172.16.63.206:57820 | NULL | Connect     |    0 | Reading from net                                              | NULL                  |    0.000 |
      		 
      +---------+----------------------+---------------------+------+-------------+------+---------------------------------------------------------------+-----------------------+----------+

      FInding 3. Applicable to 10.11
      Similarly, a new Binlog Dump thread will be created, but the original thread will not be terminated. Instead, the original thread will be placed in the following state.

      MariaDB [(none)]> show full processlist;
      		 
      +-------+----------+--------------------+------+-------------+------+---------------------------------+-----------------------+----------+
      		 
      | Id    | User     | Host               | db   | Command     | Time | State                           | Info                  | Progress |
      		 
      +-------+----------+--------------------+------+-------------+------+---------------------------------+-----------------------+----------+
      		 
      | 13976 | rdsRepl  | 172.16.58.41:36078 |      | Busy        | 1743 | Waiting to finalize termination | NULL                  |    0.000 |
      		 
      | 15548 | rdsAdmin | localhost          | NULL | Query       |    0 | starting                        | show full processlist |    0.000 |
      		 
      | 15940 | rdsRepl  | 172.16.58.41:58994 | NULL | Binlog Dump |  494 | starting                        | NULL                  |    0.000 |
      		 
      +-------+----------+--------------------+------+-------------+------+---------------------------------+-----------------------+----------+

      At this point, attempting to connect to the primary instance will result in a block.

      During the period when the standby machine was killed, the blocking stack of 10.5 is as follows:

      Thread 17 (LWP 2028106):
      		 
      #0  0x00007fcc358ccd26 in pthread_cond_timedwait () from /lib64/libpthread.so.0
      		 
      #1  0x0000562657feb354 in inline_mysql_cond_timedwait (src_file=0x562658670270 "/data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/log.cc", src_line=8750, abstime=0x7fc6a5428d80, mutex=0x562658d3f960 <mysql_bin_log+1152>, that=0x562658d3fa30 <mysql_bin_log+1360>) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/include/mysql/psi/mysql_thread.h:1270
      		 
      #2  MYSQL_BIN_LOG::wait_for_update_binlog_end_pos (this=this@entry=0x562658d3f4e0 <mysql_bin_log>, thd=0x7fc69c3dfc28, timeout=timeout@entry=0x7fc6a5428d80) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/log.cc:8750
      		 
      #3  0x0000562657cfe971 in wait_new_events (end_pos_ptr=<synthetic pointer>, binlog_end_pos_filename=0x7fc6a5429640 "./mysql-bin.001914", linfo=0x7fc6a5429840, info=0x7fc6a5429a60) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_repl.cc:2535
      		 
      #4  get_binlog_end_pos (linfo=0x7fc6a5429840, log=0x7fc6a5428f50, info=0x7fc6a5429a60) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_repl.cc:2655
      		 
      #5  send_one_binlog_file (start_pos=<optimized out>, linfo=0x7fc6a5429840, log=0x7fc6a5428f50, info=0x7fc6a5429a60) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_repl.cc:2815
      		 
      #6  mysql_binlog_send (thd=thd@entry=0x7fc69c3dfc28, log_ident=<optimized out>, pos=<optimized out>, pos@entry=4, flags=flags@entry=2) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_repl.cc:2960
      		 
      #7  0x0000562657ce7b76 in dispatch_command (command=COM_BINLOG_DUMP, thd=0x7fc69c3dfc28, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_class.h:1182
      		 
      #8  0x0000562657ce8393 in do_command (thd=thd@entry=0x7fc69c3dfc28) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_parse.cc:1378
      		 
      #9  0x0000562657e80400 in threadpool_process_request (thd=0x7fc69c3dfc28) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/threadpool_common.cc:370
      		 
      #10 tp_callback (c=0x562672b8e0a0) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/threadpool_common.cc:194
      		 
      #11 0x000056265809efad in worker_main (param=param@entry=0x5626723f7908) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/threadpool_generic.cc:1567
      		 
      #12 0x000056265816e9ab in pfs_spawn_thread (arg=0x7fc690059db8) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/storage/perfschema/pfs.cc:2201
      		 
      #13 0x00007fcc358c6f3b in ?? () from /lib64/libpthread.so.0
      		 
      #14 0x00007fcc357fe520 in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 15 (LWP 1432842):
      		 
      #0  0x00007fcc357f3a49 in poll () from /lib64/libc.so.6
      		 
      #1  0x00005626580a115b in poll (__timeout=28800000, __nfds=1, __fds=0x7fc6a49d1aa8) at /usr/include/bits/poll2.h:46
      		 
      #2  vio_io_wait (vio=vio@entry=0x562672512a18, event=<optimized out>, timeout=28800000) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/vio/viosocket.c:1000
      		 
      #3  0x00005626580a12c0 in vio_socket_io_wait (vio=0x562672512a18, event=<optimized out>) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/vio/viosocket.c:118
      		 
      #4  0x00005626580a13a3 in vio_read (vio=0x562672512a18, buf=0x7fc694326b28 "\001", size=4) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/vio/viosocket.c:199
      		 
      #5  0x000056265801c895 in my_real_read (net=0x7fc694146990, complen=complen@entry=0x7fc6a49d1d28, header=header@entry=1 '\001') at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/net_serv.cc:991
      		 
      #6  0x000056265801dc80 in my_net_read_packet_reallen (net=net@entry=0x7fc694146990, read_from_server=read_from_server@entry=1 '\001', reallen=reallen@entry=0x7fc6a49d1d78) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/net_serv.cc:1272
      		 
      #7  0x000056265801dd7d in my_net_read_packet (net=net@entry=0x7fc694146990, read_from_server=read_from_server@entry=1 '\001') at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/net_serv.cc:1256
      		 
      #8  0x0000562657ce832e in do_command (thd=0x7fc6941466e8) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_parse.cc:1236
      		 
      #9  0x0000562657de3dd1 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5626725fdb88, put_in_cache=put_in_cache@entry=true) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_connect.cc:1419
      		 
      #10 0x0000562657de425d in handle_one_connection (arg=arg@entry=0x5626725fdb88) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/sql/sql_connect.cc:1313
      		 
      #11 0x000056265816e9ab in pfs_spawn_thread (arg=0x562672512a18) at /data/fuxi_ci_workspace/65c4330f52186171be1c0f0a/mariadb_105_x86/storage/perfschema/pfs.cc:2201
      		 
      #12 0x00007fcc358c6f3b in ?? () from /lib64/libpthread.so.0
      		 
      #13 0x00007fcc357fe520 in clone () from /lib64/libc.so.6

      During the period when the standby machine was killed, the blocking stack of 10.11 is as follows:

      Thread 15 (LWP 230730):
      		 
      #0  0x00007f5a7f0e2d26 in pthread_cond_timedwait () from /lib64/libpthread.so.0
      		 
      #1  0x0000555e571b58cc in inline_mysql_cond_timedwait (src_file=0x555e577bd398 "/data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/log.cc", src_line=9151, abstime=0x7f595c4a6d20, mutex=0x555e57fafe40 <mysql_bin_log+1152>, that=0x555e57faff10 <mysql_bin_log+1360>) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/include/mysql/psi/mysql_thread.h:1088
      		 
      #2  MYSQL_BIN_LOG::wait_for_update_binlog_end_pos (this=this@entry=0x555e57faf9c0 <mysql_bin_log>, thd=0x7f59500ea1b8, timeout=timeout@entry=0x7f595c4a6d20) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/log.cc:9151
      		 
      #3  0x0000555e56e5d4fb in wait_new_events (end_pos_ptr=<synthetic pointer>, binlog_end_pos_filename=0x7f595c4a75e0 "./mysql-bin.000597", linfo=0x7f595c4a77e0, info=0x7f595c4a7a00) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:2531
      		 
      #4  get_binlog_end_pos (linfo=0x7f595c4a77e0, log=0x7f595c4a6ef0, info=0x7f595c4a7a00) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:2651
      		 
      #5  send_one_binlog_file (start_pos=<optimized out>, linfo=0x7f595c4a77e0, log=0x7f595c4a6ef0, info=0x7f595c4a7a00) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:2811
      		 
      #6  mysql_binlog_send (thd=thd@entry=0x7f59500ea1b8, log_ident=<optimized out>, pos=<optimized out>, pos@entry=4, flags=flags@entry=2) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:2958
      		 
      #7  0x0000555e56e375ec in dispatch_command (command=COM_BINLOG_DUMP, thd=0x7f59500ea1b8, packet=0x7f59500f1729 "", packet_length=<optimized out>, blocking=<optimized out>) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_class.h:1260
      		 
      #8  0x0000555e56e37cc3 in do_command (thd=thd@entry=0x7f59500ea1b8, blocking=blocking@entry=false) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_parse.cc:1418
      		 
      #9  0x0000555e5701ba7b in threadpool_process_request (thd=0x7f59500ea1b8) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_common.cc:438
      		 
      #10 tp_callback (c=0x555e599cdfb0) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_common.cc:252
      		 
      #11 0x0000555e572251ad in worker_main (param=param@entry=0x555e59811438) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_generic.cc:1556
      		 
      #12 0x0000555e572ed399 in pfs_spawn_thread (arg=0x555e598ce028) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/storage/perfschema/pfs.cc:2201
      		 
      #13 0x00007f5a7f0dcf3b in ?? () from /lib64/libpthread.so.0
      		 
      #14 0x00007f5a7f014520 in clone () from /lib64/libc.so.6

      10.11 When the thread becomes busy, the blocking stack is as follows:

      Thread 15 (LWP 230730):
      		 
      #0  0x00007f5a7f0e610d in ?? () from /lib64/libpthread.so.0
      		 
      #1  0x00007f5a7f0df620 in pthread_mutex_lock () from /lib64/libpthread.so.0
      		 
      #2  0x0000555e56e5a5e0 in inline_mysql_mutex_lock (src_line=527, src_file=0x555e57666f10 "/data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc", that=0x7f59500ebf10) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/include/mysql/psi/mysql_thread.h:752
      		 
      #3  THD::set_current_linfo (this=0x7f59500ea1b8, linfo=0x0) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:527
      		 
      #4  0x0000555e56e5b82f in THD::reset_current_linfo (this=0x7f59500ea1b8) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_class.h:5511
      		 
      #5  mysql_binlog_send (thd=thd@entry=0x7f59500ea1b8, log_ident=<optimized out>, pos=<optimized out>, pos@entry=4, flags=flags@entry=2) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:3017
      		 
      #6  0x0000555e56e375ec in dispatch_command (command=COM_BINLOG_DUMP, thd=0x7f59500ea1b8, packet=0x7f59500f1729 "", packet_length=<optimized out>, blocking=<optimized out>) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_class.h:1260
      		 
      #7  0x0000555e56e37cc3 in do_command (thd=thd@entry=0x7f59500ea1b8, blocking=blocking@entry=false) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_parse.cc:1418
      		 
      #8  0x0000555e5701ba7b in threadpool_process_request (thd=0x7f59500ea1b8) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_common.cc:438
      		 
      #9  tp_callback (c=0x555e599cdfb0) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_common.cc:252
      		 
      #10 0x0000555e572251ad in worker_main (param=param@entry=0x555e59811438) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_generic.cc:1556
      		 
      #11 0x0000555e572ed399 in pfs_spawn_thread (arg=0x555e598ce028) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/storage/perfschema/pfs.cc:2201
      		 
      #12 0x00007f5a7f0dcf3b in ?? () from /lib64/libpthread.so.0
      		 
      #13 0x00007f5a7f014520 in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 20 (LWP 381800):
      		 
      #0  0x00007f5a7f0e2a3c in pthread_cond_wait () from /lib64/libpthread.so.0
      		 
      #1  0x0000555e56fd63ff in inline_mysql_cond_wait (src_file=0x555e5768dc68 "/data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/semisync_master_ack_receiver.cc", src_line=197, mutex=0x555e57fabc30 <ack_receiver+16>, that=0x555e57fabc98 <ack_receiver+120>) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/include/mysql/psi/mysql_thread.h:1072
      		 
      #2  Ack_receiver::remove_slave (this=0x555e57fabc20 <ack_receiver>, thd=0x7f59500ea1b8) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/semisync_master_ack_receiver.cc:197
      		 
      #3  0x0000555e56e5f91b in kill_callback_collect (arg=<synthetic pointer>, thd=0x7f59500ea1b8) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:3532
      		 
      #4  kill_callback_collect (arg=<synthetic pointer>, thd=0x7f59500ea1b8) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:3518
      		 
      #5  THD_list_iterator::iterate<kill_callback_arg> (this=<optimized out>, arg=<synthetic pointer>, action=<optimized out>) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_class.h:1144
      		 
      #6  kill_zombie_dump_threads (thd=thd@entry=0x7f595000d598, slave_server_id=431338587) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_repl.cc:3568
      		 
      #7  0x0000555e56e36eb5 in dispatch_command (command=COM_BINLOG_DUMP, thd=0x7f595000d598, packet=0x7f5950013eb9 "\004", packet_length=<optimized out>, blocking=<optimized out>) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_parse.cc:2152
      		 
      #8  0x0000555e56e37cc3 in do_command (thd=thd@entry=0x7f595000d598, blocking=blocking@entry=false) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/sql_parse.cc:1418
      		 
      #9  0x0000555e5701ba7b in threadpool_process_request (thd=0x7f595000d598) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_common.cc:438
      		 
      #10 tp_callback (c=0x555e599ce080) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_common.cc:252
      		 
      #11 0x0000555e572251ad in worker_main (param=param@entry=0x555e59811438) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/sql/threadpool_generic.cc:1556
      		 
      #12 0x0000555e572ed399 in pfs_spawn_thread (arg=0x7f5928153748) at /data/fuxi_ci_workspace/6841978adaa24c2825509015/mariadb_105_x86/storage/perfschema/pfs.cc:2201
      		 
      #13 0x00007f5a7f0dcf3b in ?? () from /lib64/libpthread.so.0
      		 
      #14 0x00007f5a7f014520 in clone () from /lib64/libc.so.6

      Attachments

        Activity

          People

            Roel Roel Van de Paar
            ohye3188 小舟从此逝
            Votes:
            0 Vote for this issue
            Watchers:
            3 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.