Uploaded image for project: 'Percona Server for MySQL'
  1. Percona Server for MySQL
  2. PS-1511

LP #1331586: Replication stall with multi-threaded replication

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Done
    • Priority: High
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: None

      Description

      **Reported in Launchpad by Ovais Tariq last update 08-10-2014 15:59:57

      Percona Server version 5.6.17-66.0 compiled from source.

      OS: SunOS 5.11 joyent_20131105T084235Z i86pc i386 i86pc Solaris

      Periodically what happens every few days that the replication gets stalled with the coordinator thread in the state "Waiting for Slave Worker to release partition" and the worker threads in the state "Waiting for an event from Coordinator". At that point trying to stop the slave by executing "STOP SLAVE" also gets stalled, together with stalling all the further "SHOW SLAVE STAUS" calls.

      Below is how typically the processlist looks in that particular case:
      -------------------------------------------------------------------------------------------------------------------------------------------+

      Id User Host db Command Time State Info Rows_sent Rows_examined

      -------------------------------------------------------------------------------------------------------------------------------------------+

      2477 root localhost NULL Sleep 33355   NULL 1 46
      2967 system user   NULL Connect 24248 Waiting for master to send event NULL 0 0
      2968 system user   NULL Connect 24085 Waiting for Slave Worker to release partition NULL 0 0
      2969 system user   NULL Connect 24248 Waiting for an event from Coordinator NULL 0 0
      2970 system user   NULL Connect 24248 Waiting for an event from Coordinator NULL 0 0
      2971 system user   NULL Connect 24248 Waiting for an event from Coordinator NULL 0 0
      2972 system user   NULL Connect 24248 Waiting for an event from Coordinator NULL 0 0
      2973 system user   NULL Connect 24248 Waiting for an event from Coordinator NULL 0 0
      2974 system user   NULL Connect 84603 Waiting for an event from Coordinator NULL 0 0
      2975 system user   NULL Connect 84603 Waiting for an event from Coordinator NULL 0 0
      2976 system user   NULL Connect 84603 Waiting for an event from Coordinator NULL 0 0
      2977 system user   NULL Connect 84603 Waiting for an event from Coordinator NULL 0 1
      2978 system user   NULL Connect 84603 Waiting for an event from Coordinator NULL 0 0
      4268 root localhost some_db Query 871 Killing slave stop slave 0 0
      4370 root localhost some_db Sleep 4   NULL 0 0
      4377 monitoring 192.168.1.222:11159 NULL Query 464 init show slave status 0 0
      4419 root localhost NULL Query 0 init show processlist 0 0

      -------------------------------------------------------------------------------------------------------------------------------------------+
      17 rows in set (0.00 sec)

      Looking into this further, the InnoDB status shows us that one of the worker thread actually has an open transaction:
      ---TRANSACTION 53684133006, ACTIVE 24245 sec
      2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
      MySQL thread id 2977, OS thread handle 0x36, query id 56740540 Waiting for an event from Coordinator
      TABLE LOCK table `db2`.`tbl_name` /* Partition `p24` */ trx id 53684133006 lock mode IX
      RECORD LOCKS space id 3504 page no 23250 n bits 440 index `PRIMARY` of table `db2`.`tbl_name` /* Partition `p24` */ trx id 53684133006 lock_mode X locks rec but not gap

      First off all the transaction is a replicated transaction being executed by the worker thread and is still open for an unknown reason, while holding only a single row lock.
      Secondly, apparently the coordinator is blocked because the next even to apply is also to the `db2` database and hence it must wait for the worker thread id 2977 to commit the transaction. This is based on the implementation described here http://andreithedolphin.blogspot.com/2012/10/parallel-slave-in-mysql-replication.html

      The MySQL configuration is as follows:
      [mysqld]
      core-file
      user = mysql
      port = 3306
      datadir = /db
      socket = /tmp/mysql.sock
      default-storage-engine = innodb
      skip-external-locking
      log_warnings=1
      skip_name_resolve
      character-set-server = utf8mb4
      collation-server = utf8mb4_unicode_ci
      group_concat_max_len = 1000000

      server-id = 666

      1. InnoDB settings
        innodb_data_home_dir = /db
        innodb_log_group_home_dir = /db
        innodb_data_file_path = ibdata1:100M:autoextend
        innodb_buffer_pool_size = 20G
        innodb_buffer_pool_instances = 8
        innodb_log_file_size = 10G
        innodb_buffer_pool_load_at_startup=OFF
        innodb_buffer_pool_dump_at_shutdown=OFF
      2. allows for row_format=compressed
        innodb_file_format=Barracuda
        innodb_log_buffer_size = 64M
        innodb_flush_log_at_trx_commit = 0
        innodb_lock_wait_timeout = 50
        innodb_file_per_table
        innodb_doublewrite = 0
        innodb_io_capacity = 1200
        innodb_read_io_threads = 6
        innodb_write_io_threads = 6
        innodb_stats_on_metadata = OFF
      1. Slow query log settings
      2. The default logs all full table scans,tmp tables,filesorts on disk queries
        #use_global_long_query_time = 1
        #long_query_time = 0.5
        slow_query_log_file = slowquery.log
        slow_query_log = 1
        long_query_time = 3
        log_slow_filter = "full_scan,tmp_table_on_disk,filesort_on_disk"
        log_slow_verbosity = "full"
      1. Other general MySQL settings
        sync_binlog = 0
        query_cache_type = 0
        query_cache_size = 0
        max_connections = 3000
        thread_cache_size = 1000
        back_log = 1024
        thread_concurrency = 32
        innodb_thread_concurrency = 64
        tmpdir = /var/tmp
        max_allowed_packet = 24M
        max_join_size = 4294967295
        net_buffer_length = 2K
        thread_stack = 512K
        tmp_table_size = 64M
        max_heap_table_size = 64M
        table_open_cache = 2000
      1. Replication settings (master to slave)
        binlog_cache_size = 2M
        binlog_format=mixed
        log-bin = bin
        log-error = error.log
        expire_logs_days = 5
        slave-parallel-workers = 10
        master-info-repository = "table"
        relay-log-info-repository = "table"
        gtid_mode = ON
        enforce_gtid_consistency = true
        log-slave-updates
        replicate-ignore-table = mysql.user
        replicate-ignore-table = mysql.db
        replicate-ignore-table = mysql.tables_priv
        replicate-ignore-table = mysql.proxies_priv
      1. Started tuning slave catchup speed, can use more research
        slave-checkpoint-period = 1000
        slave-checkpoint-group = 2048

      I will be attaching the GDB stack traces in a follow up comment here

        Attachments

          Activity

            People

            Assignee:
            Unassigned
            Reporter:
            lpjirasync lpjirasync (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Smart Checklist