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

When binlogging enabled, committing a large transaction will freeze all other transactions until completed

    XMLWordPrintable

Details

    Description

      When a large transaction is committed (eg: an INSERT INTO..... SELECT) and binlogging is enabled, the entire workload is frozen until the large transaction has finished committing.

      This was noticed on a production server where running
      insert into <empty table> select * from <unused table>
      created an outage by locking the entire workload for long time.

      At first glance, this seems due to the large transaction holding an exclusive lock on binary log for write - hence, no other transaction is able to proceed until this finishes.

      Even in absence of large transactions, this seems quite a performance and scalability killer....

      To reproduce, on a server with binlogging enabled, just create a large table, then try to insert into a new table selecting from this one. When the insert... select will begin committing, you will see no other DML will be able to proceed.

      Confirmed community and enterprise 10.6 (info below from enterprise version).

      Processlist showing a 2nd transaction hanging:

      MariaDB [(none)]> show processlist;
      		 
      +-----+------+-----------+------+---------+------+----------+----------------------------------------------------+----------+
      		 
      | Id  | User | Host      | db   | Command | Time | State    | Info                                               | Progress |
      		 
      +-----+------+-----------+------+---------+------+----------+----------------------------------------------------+----------+
      		 
      | 142 | root | localhost | rick | Query   |  165 | Commit   | insert into bucket (junk) select junk from bucket1 |    0.000 |
      		 
      | 234 | root | localhost | NULL | Query   |    0 | starting | show processlist                                   |    0.000 |
      		 
      | 349 | root | localhost | NULL | Query   |   24 | Commit   | insert into rick.junk values()                     |    0.000 |
      		 
      +-----+------+-----------+------+---------+------+----------+----------------------------------------------------+----------+
      		 
      3 rows in set (0.000 sec)

      Relevant threads at the time of the commit:

      Thread 15 (Thread 0x7f08c807b700 (LWP 375122)):
      		 
      #0  0x00007f08ccc5d82d in __lll_lock_wait () from /lib64/libpthread.so.0
      		 
      #1  0x00007f08ccc56ad9 in pthread_mutex_lock () from /lib64/libpthread.so.0
      		 
      #2  0x000055fd5509d1d7 in inline_mysql_mutex_lock (src_file=0x55fd556e7a00 "/home/jenkins/workspace/Build-Package/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX_ON_ES_BACKUP_DEBUGSOURCE/sql/log.cc", src_line=8282, that=0x55fd55ddd2d0 <mysql_bin_log+16>) at /usr/src/debug/MariaDB-/src_0/include/mysql/psi/mysql_thread.h:752
      		 
      #3  MYSQL_BIN_LOG::trx_group_commit_leader (this=0x55fd55ddd2c0 <mysql_bin_log>, leader=0x7f08c80791b0) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:8282
      		 
      #4  0x000055fd5509d924 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=0x55fd55ddd2c0 <mysql_bin_log>, entry=0x7f08c80791b0) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:8145
      		 
      #5  0x000055fd5509de52 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=0x55fd55ddd2c0 <mysql_bin_log>, thd=0x7f0870000c58, cache_mngr=0x7f087002d958, end_ev=<optimized out>, all=<optimized out>, using_stmt_cache=<optimized out>, using_trx_cache=true, is_ro_1pc=false) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:7742
      		 
      #6  0x000055fd5509f2b7 in binlog_flush_cache (is_ro_1pc=false, using_trx=true, using_stmt=true, all=false, end_ev=0x7f08c80792d0, cache_mngr=0x7f087002d958, thd=0x7f0870000c58) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:1780
      		 
      #7  binlog_commit_flush_xid_caches (xid=295, all=false, cache_mngr=0x7f087002d958, thd=0x7f0870000c58) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:1930
      		 
      #8  MYSQL_BIN_LOG::log_and_order (this=<optimized out>, thd=0x7f0870000c58, xid=295, all=<optimized out>, need_prepare_ordered=<optimized out>, need_commit_ordered=<optimized out>) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:10334
      		 
      #9  0x000055fd54f9277e in ha_commit_trans (thd=thd@entry=0x7f0870000c58, all=all@entry=false) at /usr/src/debug/MariaDB-/src_0/sql/handler.cc:1926
      		 
      #10 0x000055fd54e78f13 in trans_commit_stmt (thd=0x7f0870000c58) at /usr/src/debug/MariaDB-/src_0/sql/transaction.cc:472
      		 
      #11 0x000055fd54d3f729 in mysql_execute_command(THD*, bool) () at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:6090
      		 
      #12 0x000055fd54d44b91 in mysql_parse(THD*, char*, unsigned int, Parser_state*) () at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:8063
      		 
      #13 0x000055fd54d47c75 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) () at /usr/src/debug/MariaDB-/src_0/sql/sql_class.h:1391
      		 
      #14 0x000055fd54d49ae2 in do_command (thd=0x7f0870000c58, blocking=blocking@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:1416
      		 
      #15 0x000055fd54e68437 in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_connect.cc:1416
      		 
      #16 0x000055fd54e6877d in handle_one_connection (arg=arg@entry=0x55fd56efb188) at /usr/src/debug/MariaDB-/src_0/sql/sql_connect.cc:1318
      		 
      #17 0x000055fd551d1842 in pfs_spawn_thread (arg=0x55fd56e6f6f8) at /usr/src/debug/MariaDB-/src_0/storage/perfschema/pfs.cc:2201
      		 
      #18 0x00007f08ccc541cf in start_thread () from /lib64/libpthread.so.0
      		 
      #19 0x00007f08cbfa4e73 in clone () from /lib64/libc.so.6
      		 
       
      		 
      Thread 14 (Thread 0x7f08c80c6700 (LWP 375105)):
      		 
      #0  0x00007f08ccc5da17 in write () from /lib64/libpthread.so.0
      		 
      #1  0x000055fd554c814d in my_write (Filedes=Filedes@entry=23, Buffer=Buffer@entry=0x55fd56d6b6d8 "567890123456789012345678901234567890123456789012345678901234567890123456789\370\023\323k", Count=Count@entry=65042, MyFlags=MyFlags@entry=564) at /usr/src/debug/MariaDB-/src_0/mysys/my_write.c:49
      		 
      #2  0x000055fd554abe17 in inline_mysql_file_write (src_file=0x55fd5577a0b8 "/home/jenkins/workspace/Build-Package/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX_ON_ES_BACKUP_DEBUGSOURCE/mysys/mf_iocache.c", flags=<optimized out>, count=65042, buffer=0x55fd56d6b6d8 "567890123456789012345678901234567890123456789012345678901234567890123456789\370\023\323k", file=23, src_line=1526) at /usr/src/debug/MariaDB-/src_0/include/mysql/psi/mysql_file.h:1176
      		 
      #3  _my_b_cache_write (info=0x55fd55ddd5e0 <mysql_bin_log+800>, Buffer=0x55fd56d6b6d8 "567890123456789012345678901234567890123456789012345678901234567890123456789\370\023\323k", Count=65042) at /usr/src/debug/MariaDB-/src_0/mysys/mf_iocache.c:1526
      		 
      #4  0x000055fd554ada82 in my_b_flush_io_cache (info=0x55fd55ddd5e0 <mysql_bin_log+800>, need_append_buffer_lock=0) at /usr/src/debug/MariaDB-/src_0/mysys/mf_iocache.c:1727
      		 
      #5  0x000055fd554ae242 in _my_b_write (info=0x55fd55ddd5e0 <mysql_bin_log+800>, Buffer=0x7f086c06e90a "67890123456789012345678901234567890123456789012345678901234567890123456789\370F\324k", Count=3239) at /usr/src/debug/MariaDB-/src_0/mysys/mf_iocache.c:559
      		 
      #6  0x000055fd550ad506 in Log_event_writer::write_internal (this=0x7f08c80c3fd0, pos=<optimized out>, len=8047) at /usr/src/debug/MariaDB-/src_0/sql/log_event_server.cc:820
      		 
      #7  0x000055fd55092cae in CacheWriter::write (len=8047, pos=<optimized out>, this=0x7f08c80c3fd0) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:7316
      		 
      #8  MYSQL_BIN_LOG::write_cache (this=<optimized out>, thd=<optimized out>, cache=0x7f086c05e4d0) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:7480
      		 
      #9  0x000055fd5509341d in MYSQL_BIN_LOG::write_transaction_or_stmt (this=this@entry=0x55fd55ddd2c0 <mysql_bin_log>, entry=entry@entry=0x7f08c80c41b0, commit_id=commit_id@entry=0) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:8633
      		 
      #10 0x000055fd5509d310 in MYSQL_BIN_LOG::trx_group_commit_leader (this=0x55fd55ddd2c0 <mysql_bin_log>, leader=0x7f08c80c41b0) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:8353
      		 
      #11 0x000055fd5509d924 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=0x55fd55ddd2c0 <mysql_bin_log>, entry=0x7f08c80c41b0) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:8145
      		 
      #12 0x000055fd5509de52 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=0x55fd55ddd2c0 <mysql_bin_log>, thd=0x7f086c000c58, cache_mngr=0x7f086c05e3a8, end_ev=<optimized out>, all=<optimized out>, using_stmt_cache=<optimized out>, using_trx_cache=true, is_ro_1pc=false) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:7742
      		 
      #13 0x000055fd5509f2b7 in binlog_flush_cache (is_ro_1pc=false, using_trx=true, using_stmt=true, all=false, end_ev=0x7f08c80c42d0, cache_mngr=0x7f086c05e3a8, thd=0x7f086c000c58) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:1780
      		 
      #14 binlog_commit_flush_xid_caches (xid=14, all=false, cache_mngr=0x7f086c05e3a8, thd=0x7f086c000c58) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:1930
      		 
      #15 MYSQL_BIN_LOG::log_and_order (this=<optimized out>, thd=0x7f086c000c58, xid=14, all=<optimized out>, need_prepare_ordered=<optimized out>, need_commit_ordered=<optimized out>) at /usr/src/debug/MariaDB-/src_0/sql/log.cc:10334
      		 
      #16 0x000055fd54f9277e in ha_commit_trans (thd=thd@entry=0x7f086c000c58, all=all@entry=false) at /usr/src/debug/MariaDB-/src_0/sql/handler.cc:1926
      		 
      #17 0x000055fd54e78f13 in trans_commit_stmt (thd=0x7f086c000c58) at /usr/src/debug/MariaDB-/src_0/sql/transaction.cc:472
      		 
      #18 0x000055fd54d3f729 in mysql_execute_command(THD*, bool) () at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:6090
      		 
      #19 0x000055fd54d44b91 in mysql_parse(THD*, char*, unsigned int, Parser_state*) () at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:8063
      		 
      #20 0x000055fd54d47c75 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) () at /usr/src/debug/MariaDB-/src_0/sql/sql_class.h:1391
      		 
      #21 0x000055fd54d49ae2 in do_command (thd=0x7f086c000c58, blocking=blocking@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:1416
      		 
      #22 0x000055fd54e68437 in do_handle_one_connection (connect=<optimized out>, put_in_cache=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_connect.cc:1416
      		 
      #23 0x000055fd54e6877d in handle_one_connection (arg=arg@entry=0x55fd56edcbb8) at /usr/src/debug/MariaDB-/src_0/sql/sql_connect.cc:1318
      		 
      #24 0x000055fd551d1842 in pfs_spawn_thread (arg=0x55fd56e6f1b8) at /usr/src/debug/MariaDB-/src_0/storage/perfschema/pfs.cc:2201
      		 
      #25 0x00007f08ccc541cf in start_thread () from /lib64/libpthread.so.0
      		 
      #26 0x00007f08cbfa4e73 in clone () from /lib64/libc.so.6

      Attachments

        Issue Links

          is blocked by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-32020 XA transaction replicates incorrectly, must be applied at XA COMMIT, not XA PREPARE

          • Critical - Crashes, loss of data, severe memory leak.
          • Stalled

          Activity

            People

              Elkin Andrei Elkin
              rpizzi Rick Pizzi
              Votes:
              7 Vote for this issue
              Watchers:
              20 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.