| Bug #84887 | slave_rows_search_algorithms with HASH_SCAN too slow | ||
|---|---|---|---|
| Submitted: | 8 Feb 2017 13:49 | Modified: | 26 Oct 2017 10:04 |
| Reporter: | dennis gao | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Row Based Replication ( RBR ) | Severity: | S4 (Feature request) |
| Version: | 5.7.16 | OS: | CentOS |
| Assigned to: | CPU Architecture: | Any | |
[8 Feb 2017 13:57]
dennis gao
We also do the following tests: 1. drop the supplier table, and re-create a new supplier with primary key: CREATE TABLE `supplier` ( `s_suppkey` int(11) NOT NULL, `s_name` char(25) NOT NULL, `s_address` varchar(40) NOT NULL, `s_nationkey` int(11) NOT NULL, `s_phone` char(15) NOT NULL, `s_acctbal` decimal(15,2) NOT NULL, `s_comment` varchar(101) NOT NULL, primary key (s_suppkey) ) ENGINE=InnoDB DEFAULT CHARSET=utf8; Also load 200000 rows into the table. Do the following update on master: Update supplier set s_name = 'xxx'; The master cost 4.53s to execute, and the slave cost 10s to replica. 2. drop the supplier table, and re-create a new supplier with a key: CREATE TABLE `supplier` ( `s_suppkey` int(11) NOT NULL, `s_name` char(25) NOT NULL, `s_address` varchar(40) NOT NULL, `s_nationkey` int(11) NOT NULL, `s_phone` char(15) NOT NULL, `s_acctbal` decimal(15,2) NOT NULL, `s_comment` varchar(101) NOT NULL, key (s_address) ) ENGINE=InnoDB DEFAULT CHARSET=utf8; Also load 200000 rows into the table, and all values for s_address are the same. Do the following update on master: Update supplier set s_name = 'xxx'; The master cost 6.43s to execute, and the slave cost 36min to replica. 3. drop the supplier table, and re-create a new supplier with a key: CREATE TABLE `supplier` ( `s_suppkey` int(11) NOT NULL, `s_name` char(25) NOT NULL, `s_address` varchar(40) NOT NULL, `s_nationkey` int(11) NOT NULL, `s_phone` char(15) NOT NULL, `s_acctbal` decimal(15,2) NOT NULL, `s_comment` varchar(101) NOT NULL, key (s_suppkey) ) ENGINE=InnoDB DEFAULT CHARSET=utf8; Also load 200000 rows into the table, and all values for s_suppkey are the different. Do the following update on master: Update supplier set s_name = 'xxx'; The master cost 3.11s to execute, and the slave cost 8s to replica.
[16 May 2017 15:03]
MySQL Verification Team
Hi! First of all, "add 200 k rows" is not exactly a detailed test case. However, there is something more important then that. Your bug looks like a duplicate of : https://bugs.mysql.com/bug.php?id=84287&thanks=1¬ify=128 In order to check that can you do ANALYZE TABLE on the master after the INSERT and after the UPDATE. If the performance results change, then this is a duplicate.
[29 May 2017 8:17]
dennis gao
It is not a duplicated bug of 84287, and it has been verified by percona(https://bugs.launchpad.net/percona-server/+bug/1666923). You can find the repeat test case from the percona bug list : https://bugs.launchpad.net/percona-server/+bug/1666923/+attachment/4830671/+files/bug16669... Thanks.
[29 May 2017 17:34]
MySQL Verification Team
Hi! I have downloaded a test case, but before I attempt a reproduction, please do confirm that you have tried adding ANALYZE command as we suggested. Have you noticed any improvement in the performance ????
[30 Jun 2017 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[25 Oct 2017 8:39]
jiang longfei
@gao 【description】 test the master and slave's time when add the "analyze table table_name" compare to before add this sql; 【practice】 Master doesn't use analyze: (1) build table and Import data: Sgrdb> CREATE TABLE `supplier` `s_suppkey`, int (11) NOT NULL, `s_name`, char (25) NOT NULL, `s_address`, varchar (40) NOT NULL, `s_nationkey`, int (11) NOT NULL, `s_phone` - char (15) NOT NULL, `s_acctbal` - decimal (15,2) NOT NULL, `s_comment`, varchar (101) NOT NULL, - > key (s_address) DEFAULT CHARSET=utf8 - > ENGINE=InnoDB); Query OK, 0 rows affected (0.22 sec) Sgrdb -udbscale -pabc123 -P23306 -h172.16.130.199 test # < bug1666923.sql (2) update s_name Sgrdb> update supplier set s_name='abc'; Query OK, 131072 rows affected (2.23 sec) Rows matched: 131072 Changed: 131072 Warnings: 0 Master cost 2.23s, slave cost 511 s The use of master in analyze: (1) build table and Import data: Sgrdb> CREATE TABLE `supplier` `s_suppkey`, int (11) NOT NULL, `s_name`, char (25) NOT NULL, `s_address`, varchar (40) NOT NULL, `s_nationkey`, int (11) NOT NULL, `s_phone`, char (15) NOT NULL, `s_acctbal` - decimal (15,2) NOT NULL, `s_comment`, varchar (101) NOT NULL, - > key (s_address) DEFAULT CHARSET=utf8 - > ENGINE=InnoDB); Query OK, 0 rows affected (0.22 sec) Sgrdb -udbscale -pabc123 -P23306 -h172.16.130.199 test # < bug1666923.sql (2) anlyze table Sgrdb> analyze table supplier; +---------------+---------+----------+----------+ Table Op Msg_type | | | | Msg_text | +---------------+---------+----------+----------+ Test.supplier analyze status | | | | OK | +---------------+---------+----------+----------+ 1 row in set (0.07 sec) (3) update s_name Sgrdb> update supplier set s_name='abc'; Query OK, 131072 rows affected (2.09 sec) Rows matched: 131072 Changed: 131072 Warnings: 0 Master cost 2.1S, slave cost 510 s The use of slave in analyze: (1) build table and Import data: Sgrdb> CREATE TABLE `supplier` `s_suppkey`, int (11) NOT NULL, `s_name`, char (25) NOT NULL, `s_address`, varchar (40) NOT NULL, `s_nationkey`, int (11) NOT NULL, `s_phone`, char (15) NOT NULL, `s_acctbal` - decimal (15,2) NOT NULL, `s_comment`, varchar (101) NOT NULL, - > key (s_address) DEFAULT CHARSET=utf8 - > ENGINE=InnoDB); Query OK, 0 rows affected (0.22 sec) Sgrdb -udbscale -pabc123 -P23306 -h172.16.130.199 test # < bug1666923.sql (2) anlyze table Sgrdb> analyze table supplier; +---------------+---------+----------+----------+ Table Op Msg_type | | | | Msg_text | +---------------+---------+----------+----------+ Test.supplier analyze status | | | | OK | +---------------+---------+----------+----------+ 1 row in set (0.07 sec) (3) update s_name Sgrdb> update supplier set s_name='abc'; Query OK, 131072 rows affected (2.42 sec) Rows matched: 131072 Changed: 131072 Warnings: 0 master cost 2.4s ，slave cost 510s. 【conclusion】 It is no fluence when you ANALYZE TABLE on the master or slave after the INSERT and after the UPDATE.
[25 Oct 2017 8:40]
jiang longfei
bug_system_test_sql
Attachment: bug1666923.sql.gz (application/gzip, text), 330.85 KiB.
[25 Oct 2017 11:27]
MySQL Verification Team
Hi, You have not informed us if there is any change in the speed with the slave_rows_search_algorithms. What is the time difference between the searches without ANALYZE and with ANALYZE ??? We would require couple of performance tests prior to ANALYZE and after ANALYZE. Thank you in advance.
[25 Oct 2017 11:35]
dennis gao
My college's test in previous comment show that: The analysis table will not improve the performance. The time difference of the searches without ANALYZE and with ANALYZE are almost the same, the slave both cost about 510s to do the replica.
[25 Oct 2017 11:37]
MySQL Verification Team
Hi! Please, disregard my previous comment. There is no need for ANALYZE nor for comparing perfomance. Instead, can you make an index on s_name on master, wait until it is created on both master and slave and then try your UPDATE on both machines ?? Do note that your table is InnoDB table and that it does not have a Primary Key. It would slow down all your operations on the table. if column `s_name` is unique, then make a PK out of it, instead of just making a secondary index.
[25 Oct 2017 11:43]
dennis gao
If we add key on the s_name, the replica performance will much better. We have already test that in the previous tests. What we confusing is that: According to the manual and design about slave_rows_search_algorithms with value HASH_SCAN, it will cost one table scan + one index scan at most for one transaction replica. But if the table has a very bad secondary index, slave_rows_search_algorithms with HASH_SCAN is much slower than expect.
[25 Oct 2017 12:25]
MySQL Verification Team
Hi! Your last comment was very helpful. It helped us identify the issue. It is a known phenomena and described in our manual: https://dev.mysql.com/doc/refman/5.7/en/replication-options-slave.html Note There is only a performance advantage for INDEX_SCAN and HASH_SCAN if the row events are big enough. The size of row events is configured using --binlog-row-event-max-size. For example, suppose a DELETE statement which deletes 25,000 rows generates large Delete_row_event events. In this case if slave_rows_search_algorithms is set to INDEX_SCAN or HASH_SCAN there is a performance improvement. However, if there are 25,000 DELETE statements and each is represented by a separate event then setting slave_rows_search_algorithms to INDEX_SCAN or HASH_SCAN provides no performance improvement while executing these separate events. Also, we are aware of this behaviour. Namely, when N rows are to be UPDATED / DELETED and table has no (suitable) indices, then that table would be scanned on the slave N times. According to docs: - N transactions (N BEGIN; Table_map; Rows; COMMIT): will scan that table on the slave N times. - 1 transaction with 1 statement changing many rows (N BEGIN; Table_map; Rows; Rows; Rows; COMMIT): will scan that table on the slave 1 time. - 1 transaction with N statements changing 1 row (N BEGIN; Table_map; Rows; Table_map; Rows; Table_map; Rows; COMMIT).
[25 Oct 2017 12:27]
MySQL Verification Team
I am verifying this as a feature request, because we have an idea on how to fix it. Namely, what might be attempted, on our side, is that table is scanned once (instead of N times for N rows), while RBR rows would be scanned for each table row. That would be faster in many cases. Hence, a feature request.
[25 Oct 2017 13:31]
João Gramacho
Posted by developer: > According to the manual and design about > slave_rows_search_algorithms with value HASH_SCAN, > it will cost one table scan + one index scan at most > for one transaction replica. Can you please point the references for this? Current docs have a note: There is only a performance advantage for INDEX_SCAN and HASH_SCAN if the row events are big enough. The size of row events is configured using --binlog-row-event-max-size. For example, suppose a DELETE statement which deletes 25,000 rows generates large Delete_row_event events. In this case if slave_rows_search_algorithms is set to INDEX_SCAN or HASH_SCAN there is a performance improvement. However, if there are 25,000 DELETE statements and each is represented by a separate event then setting slave_rows_search_algorithms to INDEX_SCAN or HASH_SCAN provides no performance improvement while executing these separate events. This note is n the manual because currently it will cost to the slave one table scan + one index scan per Update_rows or Delete_rows event applied. Try increasing --binlog-row-event-max-size (default is 8Kbytes) on the server you are testing to have improvements. You can also try to use --binlog-row-image option to reduce the per-row data logged (more rows will fit in a single binary log events when using MINIMAL).
[26 Oct 2017 9:57]
dennis gao
Sorry, it is a long time. what I can find now is the below link, which illustrate the design and implementation of "slave_rows_search_algorithms with HASH_SCAN": http://rohitkalhans.blogspot.com/2012/08/Batch-operations-in-RBR.html
[26 Oct 2017 10:04]
dennis gao
In our test case, we use one single update stmt to update the whole table. I think there is enough row events in this big transaction for HASH_SCAN to improve the performance. We will test the bigger binlog-row-event-max-size latter.
[30 Oct 2017 3:18]
jiang longfei
My test results are as follows： slave not add binlog-row-event-max-size update supplier set s_name='abcabc'; master cost 3s,slave cost 588s slave add binlog-row-event-max-size=1048576(1M) update supplier set s_name='abcabc'; master cost 3s ,slave cost 591s slave add binlog-row-event-max-size=10485760 (10M) update supplier set s_name='abcabc'; master cost 3s ,slave cost 606s
[30 Oct 2017 4:09]
jiang longfei
@Sinisa Milivojevic
description:
I tested two sets of master-slave library, an update is greatly delayed for about 10 minutes, another to do the same operation requires only 10 seconds, the configuration file with the version of MySQL database are the same, I do not know why, can you help me?
nodelay master-slave:
CREATE TABLE `supplier` (
`s_suppkey` int(11) NOT NULL,
`s_name` char(25) NOT NULL,
`s_address` varchar(40) NOT NULL,
`s_nationkey` int(11) NOT NULL,
`s_phone` char(15) NOT NULL,
`s_acctbal` decimal(15,2) NOT NULL,
`s_comment` varchar(101) NOT NULL,
key (s_address)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;
import data:
sgrdb -udbscale -pabc123 -P23309 -h172.16.130.117 test1 < bug1666923.sql
update date:
update supplier set s_name='abcabc';
maseter cost 2s ,slave cost 10s
before this test，I found a problem.
delay master-slave:
CREATE TABLE `supplier` (
`s_suppkey` int(11) NOT NULL,
`s_name` char(25) NOT NULL,
`s_address` varchar(40) NOT NULL,
`s_nationkey` int(11) NOT NULL,
`s_phone` char(15) NOT NULL,
`s_acctbal` decimal(15,2) NOT NULL,
`s_comment` varchar(101) NOT NULL,
key (s_address)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;
import data:
sgrdb -udbscale -pabc123 -P23309 -h172.16.73.118 test1 < bug1666923.sql
update date:
update supplier set s_name='abcabc';
maseter cost 3.8s ,slave cost 605s
analyse:
nodelay master-slave:
>show relaylog events;
+--------------------+-----+----------------+-----------+-------------+--------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+--------------------+-----+----------------+-----------+-------------+--------------------------------------------+
| sgrdb-relay.000011 | 4 | Format_desc | 30093 | 123 | Server ver: 5.7.18-15-log, Binlog ver: 4 |
| sgrdb-relay.000011 | 123 | Previous_gtids | 30093 | 194 | 776e99ce-b97a-11e7-87aa-fa163efcb381:1-115 |
| sgrdb-relay.000011 | 194 | Rotate | 30093 | 243 | sgrdb-relay.000012;pos=4 |
+--------------------+-----+----------------+-----------+-------------+--------------------------------------------+
3 rows in set (0.00 sec)
delay master-slave:
>show relaylog events;
+--------------------+----------+----------------+-----------+-------------+--------------------------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+--------------------+----------+----------------+-----------+-------------+--------------------------------------------------------------------+
| sgrdb-relay.000006 | 4 | Format_desc | 30093 | 123 | Server ver: 5.7.18-15-log, Binlog ver: 4 |
| sgrdb-relay.000006 | 123 | Previous_gtids | 30093 | 194 | b90fdbdd-b914-11e7-8cb3-000c299dccec:1-43 |
| sgrdb-relay.000006 | 194 | Rotate | 30092 | 0 | sgrdb-bin.000001;pos=4 |
| sgrdb-relay.000006 | 241 | Format_desc | 30092 | 123 | Server ver: 5.7.18-15-log, Binlog ver: 4 |
| sgrdb-relay.000006 | 360 | Rotate | 0 | 407 | sgrdb-bin.000001;pos=154 |
| sgrdb-relay.000006 | 407 | Rotate | 0 | 454 | sgrdb-bin.000001;pos=78745153 |
| sgrdb-relay.000006 | 454 | Gtid | 30092 | 78745218 | SET @@SESSION.GTID_NEXT= 'b90fdbdd-b914-11e7-8cb3-000c299dccec:44' |
| sgrdb-relay.000006 | 519 | Query | 30092 | 78745291 | BEGIN |
| sgrdb-relay.000006 | 592 | Table_map | 30092 | 78745359 | table_id: 119 (test1.supplier) |
| sgrdb-relay.000006 | 660 | Update_rows | 30092 | 78753527 | table_id: 119 |
.
..
...
| sgrdb-relay.000006 | 58393287 | Update_rows | 30092 | 137146122 | table_id: 119 |
| sgrdb-relay.000006 | 58401423 | Update_rows | 30092 | 137154258 | table_id: 119 |
| sgrdb-relay.000006 | 58409559 | Update_rows | 30092 | 137162394 | table_id: 119 |
| sgrdb-relay.000006 | 58417695 | Update_rows | 30092 | 137170530 | table_id: 119 |
| sgrdb-relay.000006 | 58425831 | Update_rows | 30092 | 137178666 | table_id: 119 |
| sgrdb-relay.000006 | 58433967 | Update_rows | 30092 | 137186802 | table_id: 119 |
| sgrdb-relay.000006 | 58442103 | Update_rows | 30092 | 137194938 | table_id: 119 |
| sgrdb-relay.000006 | 58450239 | Update_rows | 30092 | 137200050 | table_id: 119 flags: STMT_END_F |
| sgrdb-relay.000006 | 58455351 | Xid | 30092 | 137200081 | COMMIT /* xid=114374 */ |
+--------------------+----------+----------------+-----------+-------------+--------------------------------------------------------------------+
7189 rows in set (0.06 sec)
Description: According to the manual and design about slave_rows_search_algorithms with value HASH_SCAN, it will cost one table scan + one index scan at most for one transaction replica. But slave_rows_search_algorithms with HASH_SCAN is much slower than expect. How to repeat: config slave_rows_search_algorithms as 'TABLE_SCAN,INDEX_SCAN,HASH_SCAN' for both master and slave. On master: CREATE TABLE `supplier` ( `s_suppkey` int(11) NOT NULL, `s_name` char(25) NOT NULL, `s_address` varchar(40) NOT NULL, `s_nationkey` int(11) NOT NULL, `s_phone` char(15) NOT NULL, `s_acctbal` decimal(15,2) NOT NULL, `s_comment` varchar(101) NOT NULL ) ENGINE=InnoDB DEFAULT CHARSET=utf8 load 200000 rows into table supplier. Then do the following update operation: Update supplier set s_name = 'xxx'; The update sql cost about 4.48s. But the slave cost about 18min to replica this transaction. Use the perf top, we can get the following: 11.97% mysqld [.] crc32 4.99% mysqld [.] PolicyMutex<TTASEventMutex<GenericPolicy> >::enter 4.45% lic-2.17.so [.] __memmove_ssse3_back 4.21% mysqld [.] row_sel_field_store_in_mysql_format_func 4.61% mysqld [.] Hash_slave_rows::make_hash_key 3.52% mysqld [.] row_search_mvcc 3.33% mysqld [.] PolicyMutex<TTASEventMutex<GenericPolicy> >::exit 1.91% mysqld [.] row_sel_store_mysql_field_func Use gdb attach to the sql thread, we can get the following: (gdb) bt #0 0x00007f4b109aee40 in __memmove_ssse3_back () from /lib64/libc.so.6 #1 0x000000000102f54a in row_sel_store_mysql_field_func (mysql_rec=0x7f47f00348c0 "NI\017", prebuilt=0x7f47f01147a8, rec=<optimized out>, offsets=0x7f465230b6d0, field_no=7, templ=0x7f47f0029548) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/storage/innobase/row/row0sel.cc:3181 #2 0x000000000102fad4 in row_sel_store_mysql_rec (mysql_rec=0x7f47f00348c0 "NI\017", prebuilt=0x7f47f01147a8, rec=0x7f4ae66275cd "", vrow=0x0, rec_clust=0, index=0x7f47f80208c8, offsets=0x7f465230b6d0) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/storage/innobase/row/row0sel.cc:3323 #3 0x000000000103565d in row_search_mvcc (buf=0x7f47f00348c0 "NI\017", mode=PAGE_CUR_G, prebuilt=0x7f47f01147a8, match_mode=0, direction=1) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/storage/innobase/row/row0sel.cc:5782 #4 0x0000000000f4477e in ha_innobase::general_fetch (this=0x7f47f0048ed0, buf=0x7f47f00348c0 "NI\017", direction=1, match_mode=0) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/storage/innobase/handler/ha_innodb.cc:8923 #5 0x00000000007e485d in handler::ha_rnd_next (this=0x7f47f0048ed0, buf=0x7f47f00348c0 "NI\017") at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/handler.cc:2913 #6 0x0000000000ea39a7 in Rows_log_event::do_scan_and_update (this=0x7f47f0004580, rli=0x760f9e0) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/log_event.cc:10289 #7 0x0000000000ea4522 in Rows_log_event::do_apply_event (this=0x7f47f0004580, rli=0x760f9e0) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/log_event.cc:10912 #8 0x0000000000ea5bd8 in Log_event::apply_event (this=0x7f47f0004580, rli=0x760f9e0) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/log_event.cc:3233 #9 0x0000000000ee8096 in apply_event_and_update_pos (ptr_ev=0x7f465230c718, thd=0x7f47f00008c0, rli=0x760f9e0) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_slave.cc:4701 #10 0x0000000000ee93e9 in exec_relay_log_event (thd=0x7f47f00008c0, rli=0x760f9e0) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_slave.cc:5211 #11 0x0000000000eeb296 in handle_slave_sql (arg=<optimized out>) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/sql/rpl_slave.cc:7305 #12 0x00000000011cf5f4 in pfs_spawn_thread (arg=0x7f47f8010df0) at /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/storage/perfschema/pfs.cc:2188 #13 0x00007f4b11c8cdf5 in start_thread () from /lib64/libpthread.so.0 #14 0x00007f4b109561ad in clone () from /lib64/libc.so.6 (gdb) quit