Bug #74328 serious tps decline if gtid is enabled in 5.7
Submitted: 11 Oct 2014 4:54 Modified: 2 Mar 2015 11:21
Reporter: zhai weixiang (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.7.5 OS:Any
Assigned to: CPU Architecture:Any

[11 Oct 2014 4:54] zhai weixiang
Description:
MySQL Version: 5.7.5

dataset: 400 sysbench tables(In 4 databases, and each db has 100 tables), each table has 100,000 records

workload:
item_id = sb_rand_uniform(1, oltp_table_size)
table_name = "sbtest".. sb_rand_uniform(1, oltp_tables_count)
c_val = sb_rand_str("###########-###########-###########-###########-###########-###########-###########-###########-###########-###########")
query = "UPDATE " .. table_name .. " SET c='" .. c_val .. "',k=k+1 WHERE id=" .. item_id

sysbench command:

sysbench/sysbench --debug=off --test=$lua --oltp-tables-count=100  --oltp-point-selects=0 --oltp-table-size=100000 --num-threads=$1 --max-requests=10000000000 --max-time=7200000 --oltp-auto-inc=off --mysql-engine-trx=yes --mysql-table-engine=innodb --oltp-test-mod=complex --mysql-db=$2  --mysql-host=$host  --mysql-port=$port  --mysql-user=xx run

With Gtid:
TPS = 17000

Without Gtid:
TPS = 29000

Besides, I also tested 5.6.21 and the performance is completely different under same workload: 
With Gtid: 32000 TPS, Without Gtid:34000 TPS

How to repeat:
described above

Suggested fix:
I don't know
[11 Oct 2014 5:01] zhai weixiang
configure file

[mysqld_safe]
pid-file=/u01/my57/run/mysqld.pid
malloc-lib=/u01/mysql/lib/libjemalloc.so

[mysql]
port=13306
prompt=\\u@\\d \\r:\\m:\\s>
default-character-set=utf8
no-auto-rehash
#skip-insecure-warning

[client]
port=13306
socket=/u01/my57/run/mysql.sock

[mysqld]
#dir
basedir=/u01/mysql
datadir=/u01/my57/data
tmpdir=/u01/my57/tmp
lc_messages_dir=/u01/my57/share
log-error=/u01/my57/log/alert.log
slow_query_log_file=/u01/my57/log/slow.log
general_log_file=/u01/my57/log/general.log
socket=/u01/my57/run/mysql.sock
core-file
#delay_log_flush_for_prepare=1
#binlog_skip_sync_stage = 1
#binlog_order_commits=0

#innodb
#innodb_kill_idle_transaction = 10
#innodb_page_cleaner_adaptive_sleep = 1
#innodb_quick_check_table_lock = 1
#innodb_log_binlog_pos = 0
#innodb_page_cleaners = 4
#innodb_doublewrite_tablespaces=4
innodb_buffer_pool_load_at_startup=1
innodb_buffer_pool_dump_at_shutdown=1
innodb_doublewrite=1
innodb_stats_persistent=0
innodb_data_home_dir=/u01/my57/data
innodb_log_group_home_dir=/u01/my57/data
innodb_data_file_path = ibdata1:4G;ibdata2:16M:autoextend
innodb_buffer_pool_size=80G
innodb_buffer_pool_instances=8
innodb_log_files_in_group=4

innodb_log_file_size=4G
innodb_log_buffer_size=200M
innodb_flush_log_at_trx_commit=2
innodb_max_dirty_pages_pct_lwm=10
innodb_max_dirty_pages_pct=60
innodb_thread_concurrency=32
innodb_read_io_threads=8
innodb_write_io_threads=8
innodb_open_files=60000
innodb_file_format=Barracuda
innodb_file_per_table=1
innodb_flush_method=O_DIRECT
innodb_change_buffering=all
innodb_adaptive_flushing=ON
innodb_flush_neighbors=0
innodb_adaptive_hash_index=OFF
innodb_old_blocks_time=1000
innodb_stats_on_metadata=ON
innodb_read_ahead_threshold=0
innodb_use_native_aio=1
innodb_lock_wait_timeout=5
innodb_rollback_on_timeout=0
innodb_purge_threads=8
innodb_strict_mode=1
transaction-isolation=READ-COMMITTED

innodb_disable_sort_file_cache=ON
innodb_io_capacity_max=6000
innodb_io_capacity=2000

innodb_lru_scan_depth=8194

metadata_locks_hash_instances=256
metadata_locks_cache_size=32768
innodb_sync_array_size=16
innodb_print_all_deadlocks

innodb_checksum_algorithm=CRC32

#myisam
myisam_sort_buffer_size=64M
concurrent_insert=2
delayed_insert_timeout=300

#binlog
log-bin=/u01/my57/log/mysql-bin
server_id=3017441834
binlog_cache_size=32K
max_binlog_cache_size=2G
max_binlog_size=500M
binlog-format=ROW
sync_binlog=1000
log-slave-updates=1
expire_logs_days=0

#server
port=13306
skip-name-resolve
skip-ssl
max_connections=21000
max_user_connections=20200
max_connect_errors=65536
max_allowed_packet=128M
connect_timeout=8
net_read_timeout=30
net_write_timeout=60
back_log=1024

default-storage-engine=INNODB
character-set-server=utf8
lower_case_table_names=1
skip-external-locking
open_files_limit=65536
safe-user-create
local-infile=1
sql_mode="STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE"
performance_schema=ON
performance_schema_instrument='%=ON'

log_slow_admin_statements=1
log_warnings=1
long_query_time=1
slow_query_log=1
general_log=0

query_cache_type=0
query_cache_limit=1M
query_cache_min_res_unit=1K

table_definition_cache=2000
table_open_cache_instances = 16
table_open_cache=8000

thread_stack=512K
thread_cache_size=256
read_rnd_buffer_size=128K
sort_buffer_size=256K
join_buffer_size=128K
read_buffer_size=128K

# optimizer
eq_range_index_dive_limit=200 # default is 10

#replication
master-info-file=/u01/my57/log/master.info
relay-log=/u01/my57/log/relaylog
relay_log_info_file=/u01/my57/log/relay-log.info
relay-log-index=/u01/my57/log/mysqld-relay-bin.index
slave_load_tmpdir=/u01/my57/tmp
slave_type_conversions="ALL_NON_LOSSY"
slave_net_timeout=4
skip-slave-start
sync_master_info=1000
sync_relay_log_info=1000

rpl_stop_slave_timeout=300
slave_checkpoint_group=1024
slave_checkpoint_period=300
slave_parallel_workers=8
#slave_pr_mode=TABLE
slave_pending_jobs_size_max=1073741824
slave_rows_search_algorithms='TABLE_SCAN,INDEX_SCAN,HASH_SCAN'

slave_sql_verify_checksum=OFF
master_verify_checksum=OFF

gtid_mode=ON
enforce_gtid_consistency=ON

master_info_repository=TABLE
relay_log_info_repository=TABLE
[11 Oct 2014 5:08] zhai weixiang
With Gtid

root@performance_schema 01:06:58>SELECT COUNT_STAR, SUM_TIMER_WAIT, AVG_TIMER_WAIT, EVENT_NAME FROM events_waits_summary_global_by_event_name where COUNT_STAR > 0 and EVENT_NAME like 'wait/synch/%' order by SUM_TIMER_WAIT desc limit 20;
+------------+------------------+----------------+------------------------------------------------------+
| COUNT_STAR | SUM_TIMER_WAIT   | AVG_TIMER_WAIT | EVENT_NAME                                           |
+------------+------------------+----------------+------------------------------------------------------+
|    1109248 | 4509147749703152 |     4065049052 | wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done         |
|    6420883 |  292234826622468 |       45513168 | wait/synch/mutex/innodb/log_sys_mutex                |
|     889134 |   57166138749988 |       64293868 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_done        |
|    1781511 |   50964979799744 |       28607704 | wait/synch/mutex/sql/Gtid_state                      |
|          1 |   45873925200592 | 45873925200592 | wait/synch/cond/sql/COND_compress_gtid_table         |
|    3568938 |   28611092663504 |        8016296 | wait/synch/mutex/innodb/trx_sys_mutex                |
|    3675195 |    8225176579964 |        2237988 | wait/synch/mutex/innodb/lock_mutex                   |
|      30105 |    4438806931112 |      147443864 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_commit      |
|      40064 |    3441391389848 |       85897232 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log         |
|   18707921 |    2599484777364 |         138648 | wait/synch/sxlock/innodb/hash_table_locks            |
|    4364910 |    1828980399428 |         418996 | wait/synch/mutex/innodb/fil_system_mutex             |
|    1778336 |    1583201609036 |         889876 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_flush_queue |
|    6170459 |    1390264180032 |         224976 | wait/synch/mutex/innodb/redo_rseg_mutex              |
|     104348 |    1369859293268 |       13127524 | wait/synch/sxlock/innodb/fil_space_latch             |
|    1786532 |     951379856040 |         532356 | wait/synch/mutex/sql/LOCK_table_cache                |
|    2875920 |     634588169072 |         220616 | wait/synch/sxlock/innodb/index_tree_rw_lock          |
|      39661 |     609753893780 |       15373796 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_sync        |
|    3573633 |     607317997532 |         169604 | wait/synch/mutex/sql/THD::LOCK_query_plan            |
|    2680708 |     590123574968 |         219744 | wait/synch/rwlock/sql/gtid_commit_rollback           |
|     892775 |     550515821176 |         616504 | wait/synch/rwlock/sql/LOCK_grant                     |
+------------+------------------+----------------+------------------------------------------------------+
20 rows in set (0.40 sec)

Without Gtid

root@performance_schema 12:51:14>SELECT COUNT_STAR, SUM_TIMER_WAIT, AVG_TIMER_WAIT, EVENT_NAME FROM events_waits_summary_global_by_event_name where COUNT_STAR > 0 and EVENT_NAME like 'wait/synch/%' order by SUM_TIMER_WAIT desc limit 20;
+------------+-------------------+----------------+------------------------------------------------------+
| COUNT_STAR | SUM_TIMER_WAIT    | AVG_TIMER_WAIT | EVENT_NAME                                           |
+------------+-------------------+----------------+------------------------------------------------------+
|   10100651 | 18164607859001768 |     1798360044 | wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done         |
|   48427874 |  2316750818494156 |       47838792 | wait/synch/mutex/innodb/log_sys_mutex                |
|    6641704 |   585858214539768 |       88208904 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_done        |
|   25409034 |   209482268474720 |        8244324 | wait/synch/mutex/innodb/trx_sys_mutex                |
|     377500 |   151989803960364 |      402621584 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_commit      |
|    2191113 |    89027108409884 |       40630840 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log         |
|   28212573 |    38132563991580 |        1351600 | wait/synch/mutex/innodb/lock_mutex                   |
|  135819407 |    20095982265148 |         147804 | wait/synch/sxlock/innodb/hash_table_locks            |
|    2104212 |    17099978554800 |        8126168 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_sync        |
|     777003 |    15699515407396 |       20205112 | wait/synch/sxlock/innodb/fil_space_latch             |
|   42433695 |    14716938967864 |         346620 | wait/synch/mutex/innodb/redo_rseg_mutex              |
|   33012269 |    11722445478676 |         354904 | wait/synch/mutex/innodb/fil_system_mutex             |
|   13283654 |     6773980202676 |         509684 | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_flush_queue |
|   13318772 |     5563277552836 |         417688 | wait/synch/mutex/sql/LOCK_table_cache                |
|   22133014 |     4706092152240 |         212332 | wait/synch/sxlock/innodb/index_tree_rw_lock          |
|   26589564 |     4227353591448 |         158704 | wait/synch/mutex/sql/THD::LOCK_query_plan            |
|    6643341 |     3907978485888 |         588164 | wait/synch/rwlock/sql/LOCK_grant                     |
|   19939438 |     3275110715264 |         163936 | wait/synch/mutex/sql/THD::LOCK_thd_data              |
|   43835961 |     1990693953520 |          45344 | wait/synch/mutex/innodb/srv_threads_mutex            |
|    2218575 |     1466572798444 |         660976 | wait/synch/mutex/innodb/buf_pool_mutex               |
+------------+-------------------+----------------+------------------------------------------------------+
20 rows in set (0.47 sec)
[11 Oct 2014 7:00] zhai weixiang
I've run the same case in 5.7.4 and the results is not so bad..with gtid got 28000 TPS. 

I think may be this regress is caused by this change:
http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/8142

before this change, only need to update gtid_owned  while  finish_commit->Gtid_state::update_on_commit is called.

after this change, need to update gtid_owned and gtid_executed while while  finish_commit->Gtid_state::update_on_commit is called.

And we may run finish_commit under high concurrency.... So more work done in update_on_commit may lead to more performance decline...
[11 Oct 2014 7:15] zhai weixiang
My last comment seems incorrect. may be lead by some other Revision... I am not sure.
[11 Oct 2014 7:34] zhai weixiang
Some differents between 5.7.4 and 5.7.5

In 5.7.4, gtid_executed is updated in  MYSQL_BIN_LOG::write_cache

quoted code:
6242
6243       global_sid_lock->rdlock();
6244       if (gtid_state->update_on_flush(thd) != RETURN_STATUS_OK)
6245       {
6246         global_sid_lock->unlock();
6247         goto err;
6248       }
6249       global_sid_lock->unlock();
6250     }

In 5.7.5. gtid_executed is updated in finish_commit->Gtid_state::update_on_commit->Gtid_state::update_gtids_impl

My last last comment may still make sense :)
[17 Oct 2014 1:40] zhai weixiang
I can always repeat the regression. If you need more information, please let me know..:)
[12 Nov 2014 4:34] zhai weixiang
May be related.  just for record.
http://bazaar.launchpad.net/~mysql/mysql-server/5.7/revision/8460
[2 Mar 2015 11:21] David Moss
thanks for your feedback. This has been fixed in an upcoming version and the following was added to the changelog:
The GTIDs of transactions committed in a group were not added to gtid_executed in order and this sometimes caused temporary gaps in gtid_executed. When these gaps occurred, the server would have to add and remove intervals from the GTID set, and this requires a mutex, which would cause contention and could reduce performance. The fix ensures that GTIDs are added to gtid_executed in the same commit order without gaps.
[2 Mar 2015 11:23] David Moss
Posted by developer:
 
Thanks for your feedback. This has been fixed in an upcoming version and the following was added to the changelog:
The GTIDs of transactions committed in a group were not added to gtid_executed in order and this sometimes caused temporary gaps in gtid_executed. When these gaps occurred, the server would have to add and remove intervals from the GTID set, and this requires a mutex, which would cause contention and could reduce performance. The fix ensures that GTIDs are added to gtid_executed in the same commit order without gaps.
[12 Dec 2016 2:58] Jie Zhou
It seems that gtid still raise a performance decline in 5.7.15
[12 Dec 2016 4:38] Shane Bester
Hi,
  This bug was fixed in 5.7.6.
  Please open a new bug report for further problems.
Thanks,