| 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: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 5.7.5 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[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]
MySQL Verification Team
Hi, This bug was fixed in 5.7.6. Please open a new bug report for further problems. Thanks,
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