Mysql – slow writes on percona / mariadb server only when replication is running

mariadbMySQLpercona-serverreplication

Hi I am trying to migrate to percona server from mysql 5.6 on windows.
In my development machine for percona is running of centos 6.5 which is installed on vmware 5.5 sphere.

Our business application is performing very well on the server however when and on when we enable circular replication, the business app lags behind on both ends. We noticed that the writes (updates, deletes etc ) are taking several seconds to complete instead of ms ( when replication is turned off )

We do not have this problem on windows. Only on percona. Since its mainly happening with writes and replication, it may have to do with the binary logs and i/o of the harddisk. I tried various settings, like turning off doublewrite, playing with the logs cache file size etc no luck.

update: i been following some mysql tuning guides, even trying to profile the server.
It is weird as the app performs well when replication is off. i given the developers the slow query logs and told them to look at them, however when replication is off, these queries are not slow, my slow query log % is 0% compared to 16% when replication is on

**update 2: On the extact same infrastructure same mahcines, 2 new VM were added to test replication using stock Mysql5.6 com edition. Everything is working fine without problems, could it be just a percona issue.. Mariadb 10 has the same problem

** update 3: I been trying to isolate where the slow down is occurring on percona and mariadb. My cnf.file has all the replication stuff on. My business app performs fine. All the logs files are updated without any problems. Performance is good. Only when I start the slave, the master server performs badly. When I stop the slave from mysql command line, the performance is back.

While the server is in circular replication, our business app performs poorly,and while in this state I also conducted the following tests

using sysbench

sysbench --db-driver=mysql --num-threads=16 --max-requests=10000 --test=oltp --oltp-table-size=500000 --mysql-host="192.168.1.251" --oltp-test-mode=complex --mysql-user=admin --mysql-password=adm run
sysbench 0.4.12:  multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 16

Doing OLTP test.
Running mixed OLTP test
Using Special distribution (12 iterations,  1 pct of values are returned in 75 pct cases)
Using "BEGIN" for starting transactions
Using auto_inc on the id column
Maximum number of requests for OLTP test is limited to 10000
Threads started!
Done.

OLTP test statistics:
    queries performed:
        read:                            140000
        write:                           50000
        other:                           20000
        total:                           210000
    transactions:                        10000  (1098.37 per sec.)
    deadlocks:                           0      (0.00 per sec.)
    read/write requests:                 190000 (20869.10 per sec.)
    other operations:                    20000  (2196.75 per sec.)

Test execution summary:
    total time:                          9.1044s
    total number of events:              10000
    total time taken by event execution: 145.5482
    per-request statistics:
         min:                                  4.87ms
         avg:                                 14.55ms
         max:                                197.28ms
         approx.  95 percentile:              19.67ms

Threads fairness:
    events (avg/stddev):           625.0000/12.79
    execution time (avg/stddev):   9.0968/0.00

I have also included mysqltuner profile as well.

[OK] Currently running supported MySQL version 5.6.17-65.0-56-log
[OK] Operating on 64-bit architecture

-------- Storage Engine Statistics -------------------------------------------
[--] Status: +ARCHIVE +BLACKHOLE +CSV -FEDERATED +InnoDB +MRG_MYISAM
[--] Data in InnoDB tables: 588M (Tables: 219)
[--] Data in PERFORMANCE_SCHEMA tables: 0B (Tables: 52)
[!!] Total fragmented tables: 11

-------- Security Recommendations  -------------------------------------------
[OK] All database users have passwords assigned

-------- Performance Metrics -------------------------------------------------
[--] Up for: 11m 44s (1K q [1.781 qps], 368 conn, TX: 1M, RX: 274K)
[--] Reads / Writes: 87% / 13%
[--] Total buffers: 5.1G global + 1.1M per thread (200 max threads)
[OK] Maximum possible memory usage: 5.3G (68% of installed RAM)
[!!] Slow queries: 6% (82/1K)
[OK] Highest usage of available connections: 1% (3/200)
[OK] Key buffer size / total MyISAM indexes: 32.0M/97.0K
[OK] Query cache efficiency: 33.2% (130 cached / 392 selects)
[OK] Query cache prunes per day: 0
[OK] Sorts requiring temporary tables: 3% (2 temp sorts / 61 sorts)
[!!] Joins performed without indexes: 9
[OK] Temporary tables created on disk: 1% (4 on disk / 222 total)
[OK] Thread cache hit rate: 97% (9 created / 368 connections)
[OK] Table cache hit rate: 97% (379 open / 390 opened)
[OK] Open file limit used: 0% (54/65K)
[OK] Table locks acquired immediately: 100% (645 immediate / 645 locks)
[OK] InnoDB buffer pool / data size: 5.0G/588.9M
[OK] InnoDB log waits: 0
-------- Recommendations -----------------------------------------------------


# Percona Toolkit MySQL Summary Report #######################
              System time | 2014-07-11 19:43:05 UTC (local TZ: SAST +0200)
# Instances ##################################################
  Port  Data Directory             Nice OOM Socket
  ===== ========================== ==== === ======
        /var/lib/mysql/            0    0   /var/lib/mysql/mysql.sock
# MySQL Executable ###########################################
       Path to executable | /usr/sbin/mysqld
              Has symbols | No
# Report On Port 3306 ########################################
                     User | admin@localhost
                     Time | 2014-07-11 21:43:04 (SAST)
                 Hostname | mobeni-standalone
                  Version | 5.6.17-65.0-56-log Percona Server (GPL), Release 65.0, Revision 587
                 Built On | Linux x86_64
                  Started | 2014-07-11 21:26 (up 0+00:16:59)
                Databases | 6
                  Datadir | /var/lib/mysql/
                Processes | 2 connected, 2 running
              Replication | Is a slave, has 1 slaves connected
                  Pidfile | /var/lib/mysql/mysql.pid (exists)
# Processlist ################################################

  Command                        COUNT(*) Working SUM(Time) MAX(Time)
  ------------------------------ -------- ------- --------- ---------
  Binlog Dump GTID                      1       1      1000      1000
  Connect                               2       2      2000      1000
  Query                                 1       1         0         0

  User                           COUNT(*) Working SUM(Time) MAX(Time)
  ------------------------------ -------- ------- --------- ---------
  admin                                 2       2      1000      1000
  system user                           2       2      2000      1000

  Host                           COUNT(*) Working SUM(Time) MAX(Time)
  ------------------------------ -------- ------- --------- ---------
  10.2.0.2                              1       1      1000      1000
                                        2       2      2000      1000
  localhost                             1       1         0         0

  db                             COUNT(*) Working SUM(Time) MAX(Time)
  ------------------------------ -------- ------- --------- ---------
  NULL                                  4       4      3000      1000

  State                          COUNT(*) Working SUM(Time) MAX(Time)
  ------------------------------ -------- ------- --------- ---------
  init                                  1       1         0         0
  Master has sent all binlog to         1       1      1000      1000
  Slave has read all relay log;         1       1      1000      1000
  Waiting for master to send eve        1       1      1000      1000

# Status Counters (Wait 10 Seconds) ##########################
Variable                                Per day  Per second     16 secs
Binlog_cache_use                           1000
Bytes_received                         30000000         350         225
Bytes_sent                            100000000        1250        2000
Com_admin_commands                          600
Com_commit                                  600
Com_delete                                 1250
Com_insert                                 1500
Com_select                                30000                       1
Com_set_option                            60000
Com_show_status                             600
Com_show_storage_engines                    500
Com_show_variables                          800
Com_stmt_close                            10000
Com_stmt_execute                          10000
Com_stmt_prepare                          10000
Com_update                                 1500
Connections                               40000
Created_tmp_disk_tables                     350
Created_tmp_files                           800
Created_tmp_tables                        22500                       4
Flush_commands                               80
Handler_commit                            25000
Handler_delete                              800
Handler_external_lock                    125000           1
Handler_prepare                            7000
Handler_read_first                         7000
Handler_read_key                      225000000        2500
Handler_read_last                           500
Handler_read_next                     100000000        1250
Handler_read_prev                           800
Handler_read_rnd                        8000000         100
Handler_read_rnd_next                 150000000        1750          30
Handler_update                         10000000         125
Handler_write                          20000000         250          30
Innodb_background_log_sync                90000                       1
Innodb_buffer_pool_bytes_data       35000000000      400000
Innodb_buffer_pool_pages_flushed          45000
Innodb_buffer_pool_pages_made_young        1500
Innodb_buffer_pool_pages_old             800000           8
Innodb_buffer_pool_read_ahead            800000           8
Innodb_buffer_pool_read_requests      900000000       10000
Innodb_buffer_pool_reads                1250000          15
Innodb_buffer_pool_write_requests        100000           1
Innodb_checkpoint_max_age           35000000000      450000
Innodb_data_fsyncs                        12500
Innodb_data_read                    35000000000      400000
Innodb_data_reads                       2000000          25
Innodb_data_writes                        50000
Innodb_data_written                  1500000000       17500
Innodb_dblwr_pages_written                45000
Innodb_dblwr_writes                        1250
Innodb_history_list_length                50000
Innodb_ibuf_free_list                       800
Innodb_ibuf_merged_delete_marks            1250
Innodb_ibuf_merged_inserts                  800
Innodb_ibuf_merges                         2000
Innodb_ibuf_segment_size                    900
Innodb_ibuf_size                             80
Innodb_log_write_requests                 80000
Innodb_log_writes                          3500
Innodb_lsn_current                  1750000000000    20000000
Innodb_lsn_flushed                  1750000000000    20000000
Innodb_lsn_last_checkpoint          1750000000000    20000000
Innodb_master_thread_active_loops         12500
Innodb_master_thread_idle_loops           70000                       1
Innodb_max_trx_id                     700000000        8000
Innodb_mem_adaptive_hash            10000000000      125000
Innodb_mem_dictionary                2000000000       22500
Innodb_mem_total                    450000000000     5000000
Innodb_mutex_os_waits                       900
Innodb_mutex_spin_rounds                  50000
Innodb_mutex_spin_waits                   25000
Innodb_os_log_fsyncs                       4500
Innodb_os_log_written                  22500000         250
Innodb_pages_created                       2000
Innodb_pages_read                       2000000          25
Innodb_pages_written                      45000
Innodb_purge_trx_id                   700000000        8000
Innodb_rows_deleted                         800
Innodb_rows_inserted                       1500
Innodb_rows_read                      400000000        5000
Innodb_rows_updated                        1000
Innodb_num_open_files                     20000
Innodb_read_views_memory                  15000
Innodb_descriptors_memory                700000           7
Innodb_s_lock_os_waits                     9000
Innodb_s_lock_spin_rounds                250000           3
Innodb_s_lock_spin_waits                   9000
Innodb_available_undo_logs                10000
Innodb_x_lock_os_waits                       80
Innodb_x_lock_spin_rounds                  4000
Innodb_x_lock_spin_waits                     80
Open_table_definitions                    25000
Opened_files                              40000                       3
Opened_table_definitions                  25000
Opened_tables                             35000
Qcache_hits                               12500
Qcache_inserts                            15000
Qcache_not_cached                         15000                       1
Queries                                  175000           2           2
Questions                                150000           1           2
Select_full_join                            800
Select_range                                600
Select_scan                               10000
Slave_received_heartbeats                    80
Slow_queries                               8000
Sort_merge_passes                           175
Sort_range                                  500
Sort_rows                               8000000         100
Sort_scan                                  5000
Table_locks_immediate                     60000
Table_open_cache_hits                    500000           6
Table_open_cache_misses                   35000
Threadpool_idle_threads                     250
Threadpool_threads                          400
Threads_created                             900
Uptime                                    90000           1           1
# Table cache ################################################
                     Size | 4096
                    Usage | 9%
# Key Percona Server features ################################
      Table & Index Stats | Disabled
     Multiple I/O Threads | Enabled
     Corruption Resilient | Enabled
      Durable Replication | Not Supported
     Import InnoDB Tables | Not Supported
     Fast Server Restarts | Not Supported
         Enhanced Logging | Disabled
     Replica Perf Logging | Disabled
      Response Time Hist. | Not Supported
          Smooth Flushing | Not Supported
      HandlerSocket NoSQL | Not Supported
           Fast Hash UDFs | Unknown
# Percona XtraDB Cluster #####################################
# Plugins ####################################################
       InnoDB compression | ACTIVE
# Query cache ################################################
         query_cache_type | ON
                     Size | 1.0M
                    Usage | 40%
         HitToInsertRatio | 100%
# Schema #####################################################
Specify --databases or --all-databases to dump and summarize schemas
# Noteworthy Technologies ####################################
                      SSL | No
     Explicit LOCK TABLES | No
           Delayed Insert | No
          XA Transactions | No
              NDB Cluster | No
      Prepared Statements | Yes
 Prepared statement count | 0
# InnoDB #####################################################
                  Version | 5.6.17-65.0
         Buffer Pool Size | 5.0G
         Buffer Pool Fill | 8%
        Buffer Pool Dirty | 0%
           File Per Table | ON
                Page Size | 16k
            Log File Size | 2 * 256.0M = 512.0M
          Log Buffer Size | 8M
             Flush Method | O_DIRECT
      Flush Log At Commit | 1
               XA Support | ON
                Checksums | ON
              Doublewrite | ON
          R/W I/O Threads | 4 4
             I/O Capacity | 200
       Thread Concurrency | 0
      Concurrency Tickets | 5000
       Commit Concurrency | 0
      Txn Isolation Level | REPEATABLE-READ
        Adaptive Flushing | ON
      Adaptive Checkpoint |
           Checkpoint Age | 0
             InnoDB Queue | 0 queries inside InnoDB, 0 queries in queue
       Oldest Transaction | 0 Seconds
         History List Len | 609
609
               Read Views | 0
         Undo Log Entries | 0 transactions, 0 total undo, 0 max undo
        Pending I/O Reads | 0 buf pool reads, 0 normal AIO, 0 ibuf AIO, 0 preads
       Pending I/O Writes | 0 buf pool (0 LRU, 0 flush list, 0 page); 0 AIO, 0 sync, 0 log IO (0 log, 0 chkp); 0 pwrites
      Pending I/O Flushes | 0 buf pool, 0 log
       Transaction States | 2xnot started
# MyISAM #####################################################
                Key Cache | 32.0M
                 Pct Used | 20%
                Unflushed | 0%
# Security ###################################################
                    Users | 8 users, 0 anon, 0 w/o pw, 0 old pw
            Old Passwords | 0
# Binary Logging #############################################
                  Binlogs | 9
               Zero-Sized | 0
               Total Size | 71.2M
            binlog_format | ROW
         expire_logs_days | 7
              sync_binlog | 1
                server_id | 1
             binlog_do_db |
         binlog_ignore_db |
# Noteworthy Variables #######################################
     Auto-Inc Incr/Offset | 10/1
   default_storage_engine | InnoDB
               flush_time | 0
             init_connect |
                init_file |
                 sql_mode | NO_AUTO_VALUE_ON_ZERO,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
         join_buffer_size | 256k
         sort_buffer_size | 256k
         read_buffer_size | 128k
     read_rnd_buffer_size | 256k
       bulk_insert_buffer | 0.00
      max_heap_table_size | 32M
           tmp_table_size | 32M
       max_allowed_packet | 16M
             thread_stack | 256k
                      log |
                log_error | /var/log/mysqld.log
             log_warnings | 1
         log_slow_queries |
log_queries_not_using_indexes | ON
        log_slave_updates | ON
# Configuration File #########################################
              Config File | /etc/my.cnf

[mysql]
port                                = 3306
socket                              = /var/lib/mysql/mysql.sock

[mysqld]
user                                = mysql
default-storage-engine              = InnoDB
socket                              = /var/lib/mysql/mysql.sock
pid-file                            = /var/lib/mysql/mysql.pid
lower-case-table-names              = 1
key-buffer-size                     = 32M
myisam-recover                      = FORCE,BACKUP
max-allowed-packet                  = 16M
max-connect-errors                  = 1000000
skip-name-resolve
sql-mode                            = STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_AUTO_VALUE_ON_ZERO,NO_ENGINE_SUBSTITUTION,NO_ZERO_DATE,NO_ZERO_IN_DATE
innodb                              = FORCE
innodb-strict-mode                  = 1
sysdate-is-now                      = 1
thread_handling                     = pool-of-threads
thread_pool_size                    = 2
datadir                             = /var/lib/mysql/
log-bin                             = /var/lib/mysql/mysql-bin
expire-logs-days                    = 14
sync-binlog                         = 1
tmp-table-size                      = 32M
max-heap-table-size                 = 32M
query-cache-type                    = 1
query-cache-size                    = 1M
max-connections                     = 200
thread-cache-size                   = 30
open-files-limit                    = 65535
table-definition-cache              = 4096
table-open-cache                    = 4096
innodb-flush-method                 = O_DIRECT
innodb-log-files-in-group           = 2
innodb-log-file-size                = 256M
innodb-flush-log-at-trx-commit      = 1
innodb-file-per-table               = 1
innodb-buffer-pool-size             = 5G
log-error                           = /var/lib/mysql/mysql-error.log
log-queries-not-using-indexes       = 1
slow-query-log                      = 1
slow-query-log-file                 = /var/lib/mysql/mysql-slow.log
binlog_format                       = ROW
log-bin                             = binlogG09
relay-log                           = relay-binG09
expire_logs_days                    = 7
log-slave-updates                   = 1
gtid_mode                           = ON
enforce-gtid-consistency            = 1
server-id                           = 1
auto_increment_increment            = 10
auto_increment_offset               = 1

[client]
user                                = admin
password                            = "adm"

[mysqldump]
max-allowed-packet                  = 512M

[MYSQLD_SAFE]
pid-file                            = mysqld.pid
log-error                           = /var/log/mysqld.log
basedir                             = /usr/
datadir                             = /var/lib/mysql
# The End ####################################################

Best Answer

You noted on the Percona discussion group that you found the culprit to be the thread pool. Then Laurynas Biveinis replied: Jul 16 (7 days ago)

Ah. Your my.cnf has thread_pool_size = 2 which seems too low and possibly explains the poor performance of thread pool. If you want to use it, make sure to tune its settings, http://www.percona.com/doc/percona-server/5.6/performance/threadpool.html