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

optimizing of binlogging of large transactions

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

          causes

          Bug - A problem which impairs or prevents the functions of the product. MDEV-34930 galera.galera_ssl_compression crashes

          • Blocker - Blocks development and/or testing work, production could not run.
          • Closed
          duplicates

          New Feature - A new feature of the product, which has yet to be developed. MDEV-33487 Reduce the blocking time for writing binlogs of large transactions

          • Major - Major loss of function.
          • Closed
          relates to

          New Feature - A new feature of the product, which has yet to be developed. MDEV-34705 Storing binlog in InnoDB

          • Major - Major loss of function.
          • In Progress

          Activity

            Transition Time In Source Status Execution Times
            Roel Van de Paar made transition -
            Open Needs Feedback
            		45d 5h 4m 3
            Andrei Elkin made transition -
            Needs Feedback Open
            		4d 13h 27m 3
            Andrei Elkin made transition -
            Open Confirmed
            		84d 6h 30m 1
            Brandon Nesterenko made transition -
            Confirmed In Review
            		207d 11h 19m 1
            Andrei Elkin made transition -
            In Review Stalled
            		41d 5h 43m 1
            Brandon Nesterenko made transition -
            Stalled In Testing
            		1d 4h 23m 1
            Brandon Nesterenko made transition -
            In Testing Stalled
            		34d 8h 41m 1
            Brandon Nesterenko made transition -
            Stalled Closed
            		1d 4h 12m 1

            People

              bnestere Brandon Nesterenko
              rpizzi Rick Pizzi (Inactive)
              Votes:
              7 Vote for this issue
              Watchers:
              23 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.