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

SHOW BINLOG EVENTS from an old log blocks writing to the current one

    XMLWordPrintable

Details

    • Bug
    • Status: Open (View Workflow)
    • Minor
    • Resolution: Unresolved
    • 10.1, 10.2, 10.3, 10.4, 10.5
    • 10.4, 10.5
    • Replication
    • None

    Description

      Note: It's quite possibly not a bug, but I spent quite some time trying to figure out the reason of unexpected long waits and connection aborts in the tests, I guess users may get puzzled too, so it's worth checking whether it really behaves as designed.

      The attached test case creates some binlog events in master-bin.000001 and flushes the binary log. Then it concurrently runs a single query (e.g. CREATE TABLE) and SHOW BINLOG EVENTS [from 'master-bin.000001'] in such a way that MTR waits for CREATE TABLE to finish, and only after that processes the result set of SHOW BINLOG EVENTS.

      However, CREATE TABLE doesn't return, it waits in MYSQL_BIN_LOG::write for SHOW BINLOG EVENTS to finish; and MTR doesn't allow SHOW BINLOG EVENTS to finish since it doesn't read the result set. So, both threads keep waiting until SHOW BINLOG EVENTS reaches net_write_timeout, then the connection running it aborts, and CREATE TABLE succeeds.

      The question is – should the query really be blocked by SHOW BINLOG EVENTS, given that binary logs have already been flushed, and the query is guaranteed to be written into another log, not the one that SHOW BINLOG EVENTS reads.

      Here are the stack traces of the threads while they are waiting.

      10.3 297746de

      Thread 29 (Thread 0x7f913cec1700 (LWP 31157)):
      #0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
      #1  0x00007f914cf4fbb5 in __GI___pthread_mutex_lock (mutex=0x5616035a6790 <mysql_bin_log+48>) at ../nptl/pthread_mutex_lock.c:80
      #2  0x0000561602899396 in safe_mutex_lock (mp=0x5616035a6768 <mysql_bin_log+8>, my_flags=0, file=0x561602b1070c "/data/src/10.3/sql/log.cc", line=6
      314) at /data/src/10.3/mysys/thr_mutex.c:293
      #3  0x000056160212b28a in inline_mysql_mutex_lock (that=0x5616035a6768 <mysql_bin_log+8>, src_file=0x561602b1070c "/data/src/10.3/sql/log.cc", src_
      line=6314) at /data/src/10.3/include/mysql/psi/mysql_thread.h:717
      #4  0x000056160213e161 in MYSQL_BIN_LOG::write (this=0x5616035a6760 <mysql_bin_log>, event_info=0x7f913cebf7d0, with_annotate=0x0) at /data/src/10.
      3/sql/log.cc:6314
      #5  0x0000561601c9b515 in THD::binlog_query (this=0x7f90d4000af0, qtype=THD::STMT_QUERY_TYPE, query_arg=0x7f90d4011558 "CREATE TABLE IF NOT EXISTS 
      xxx (a INT)", query_len=38, is_trans=false, direct=false, suppress_use=false, errcode=0) at /data/src/10.3/sql/sql_class.cc:7343
      #6  0x0000561601dcb6a3 in write_bin_log (thd=0x7f90d4000af0, clear_error=true, query=0x7f90d4011558 "CREATE TABLE IF NOT EXISTS xxx (a INT)", query
      _length=38, is_trans=false) at /data/src/10.3/sql/sql_table.cc:1994
      #7  0x0000561601dd5212 in mysql_create_table (thd=0x7f90d4000af0, create_table=0x7f90d4011668, create_info=0x7f913cebfb80, alter_info=0x7f913cebfac
      0) at /data/src/10.3/sql/sql_table.cc:5303
      #8  0x0000561601de69ee in Sql_cmd_create_table_like::execute (this=0x7f90d4011648, thd=0x7f90d4000af0) at /data/src/10.3/sql/sql_table.cc:11276
      #9  0x0000561601d00c58 in mysql_execute_command (thd=0x7f90d4000af0) at /data/src/10.3/sql/sql_parse.cc:6022
      #10 0x0000561601d0640d in mysql_parse (thd=0x7f90d4000af0, rawbuf=0x7f90d4011558 "CREATE TABLE IF NOT EXISTS xxx (a INT)", length=38, parser_state=
      0x7f913cec0630, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7810
      #11 0x0000561601cf2c54 in dispatch_command (command=COM_QUERY, thd=0x7f90d4000af0, packet=0x7f90d4008d71 "CREATE TABLE IF NOT EXISTS xxx (a INT)", 
      packet_length=38, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1848
      #12 0x0000561601cf156c in do_command (thd=0x7f90d4000af0) at /data/src/10.3/sql/sql_parse.cc:1393
      #13 0x0000561601e6ad5d in do_handle_one_connection (connect=0x5616057c0a00) at /data/src/10.3/sql/sql_connect.cc:1403
      #14 0x0000561601e6aabf in handle_one_connection (arg=0x5616057c0a00) at /data/src/10.3/sql/sql_connect.cc:1308
      #15 0x00007f914cf4d4a4 in start_thread (arg=0x7f913cec1700) at pthread_create.c:456
      #16 0x00007f914b081d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
       
      Thread 28 (Thread 0x7f913cf0c700 (LWP 31121)):
      #0  0x00007f914b0788bd in poll () at ../sysdeps/unix/syscall-template.S:84
      #1  0x00005616028f9caa in vio_io_wait (vio=0x561605736080, event=VIO_IO_EVENT_WRITE, timeout=60000) at /data/src/10.3/vio/viosocket.c:962
      #2  0x00005616028f8339 in vio_socket_io_wait (vio=0x561605736080, event=VIO_IO_EVENT_WRITE) at /data/src/10.3/vio/viosocket.c:119
      #3  0x00005616028f89ab in vio_write (vio=0x561605736080, buf=0x7f90e8069550 "') ,  ('t', NULL, 421658624, 'jhn') ,  ('merchant', NULL, 2097610752, 'friend') ,  ('hnlbvx', NULL, NULL, 'y') ,  ('nlbvxeogdbxd', NULL, 7, 'city') ,  ('secretary', NULL, -612302848, 'lbvxe') ,  ('bvx"..., size=16384) at /data/src/10.3/vio/viosocket.c:306
      #4  0x0000561601bd9562 in net_real_write (net=0x7f90e8000dd8, packet=0x7f90e8069550 "') ,  ('t', NULL, 421658624, 'jhn') ,  ('merchant', NULL, 2097610752, 'friend') ,  ('hnlbvx', NULL, NULL, 'y') ,  ('nlbvxeogdbxd', NULL, 7, 'city') ,  ('secretary', NULL, -612302848, 'lbvxe') ,  ('bvx"..., len=16384) at /data/src/10.3/sql/net_serv.cc:693
      #5  0x0000561601bd91a9 in net_write_buff (net=0x7f90e8000dd8, packet=0x7f90e800ceb0 "\021master-bin.000001\006\062\062\067\060\062\063\006Rotate\001\061\006\062\062\067\060\067\061\027master-bin.000002;pos=4! IGNORE */ INTO t1 VALUES  ('persist', NULL, NULL, 'timing') ,  ('s', NULL, 1, 'uoi') ,  ('couch', NULL, NULL, 't') ,  ('after', NULL,"..., len=65) at /data/src/10.3/sql/net_serv.cc:584
      #6  0x0000561601bd8d15 in my_net_write (net=0x7f90e8000dd8, packet=0x7f90e800ceb0 "\021master-bin.000001\006\062\062\067\060\062\063\006Rotate\001\061\006\062\062\067\060\067\061\027master-bin.000002;pos=4! IGNORE */ INTO t1 VALUES  ('persist', NULL, NULL, 'timing') ,  ('s', NULL, 1, 'uoi') ,  ('couch', NULL, NULL, 't') ,  ('after', NULL,"..., len=65) at /data/src/10.3/sql/net_serv.cc:448
      #7  0x0000561601be1f92 in Protocol::write (this=0x7f90e80010a8) at /data/src/10.3/sql/protocol.cc:966
      #8  0x0000561602152c77 in Log_event::net_send (this=0x7f90e806e970, protocol=0x7f90e80010a8, log_name=0x7f913cf0aa42 "master-bin.000001", pos=227023) at /data/src/10.3/sql/log_event.cc:1490
      #9  0x0000561601d37a67 in mysql_show_binlog_events (thd=0x7f90e8000af0) at /data/src/10.3/sql/sql_repl.cc:4054
      #10 0x0000561601cf8c88 in mysql_execute_command (thd=0x7f90e8000af0) at /data/src/10.3/sql/sql_parse.cc:3923
      #11 0x0000561601d0640d in mysql_parse (thd=0x7f90e8000af0, rawbuf=0x7f90e8012708 "SHOW BINLOG EVENTS", length=18, parser_state=0x7f913cf0b630, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7810
      #12 0x0000561601cf2c54 in dispatch_command (command=COM_QUERY, thd=0x7f90e8000af0, packet=0x7f90e8069551 ") ,  ('t', NULL, 421658624, 'jhn') ,  ('merchant', NULL, 2097610752, 'friend') ,  ('hnlbvx', NULL, NULL, 'y') ,  ('nlbvxeogdbxd', NULL, 7, 'city') ,  ('secretary', NULL, -612302848, 'lbvxe') ,  ('bvxe"..., packet_length=18, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1848
      #13 0x0000561601cf156c in do_command (thd=0x7f90e8000af0) at /data/src/10.3/sql/sql_parse.cc:1393
      #14 0x0000561601e6ad5d in do_handle_one_connection (connect=0x5616057c0a00) at /data/src/10.3/sql/sql_connect.cc:1403
      #15 0x0000561601e6aabf in handle_one_connection (arg=0x5616057c0a00) at /data/src/10.3/sql/sql_connect.cc:1308
      #16 0x00007f914cf4d4a4 in start_thread (arg=0x7f913cf0c700) at pthread_create.c:456
      #17 0x00007f914b081d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      To make the test finish faster, run with --mysqld=--net-write-timeout=<low value>. By default it's 60 seconds, so the test case takes a minute before it fails.

      Attachments

        Activity

          People

            Elkin Andrei Elkin
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:

              Git Integration

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