slave_rows_search_algorithms with HASH_SCAN too slow

Bug #1666923 reported by dennis
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MySQL Server
Unknown
Unknown
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.6
Triaged
Medium
Unassigned
5.7
Triaged
Medium
Unassigned

Bug Description

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.

I test on percona 5.7.16.

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.
============================================================
That is too slow!!!
Why one table scan plus one index scan need so many time?
============================================================

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

================================================================================================
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.

It seams, the better index will get better replica performance.
But why?
In this test, the whole table need to be updated in all cases.

dennis (gao1738)
affects: percona-playback → percona-xtradb
no longer affects: centos
dennis (gao1738)
description: updated
affects: percona-xtradb → percona-server
tags: added: performance upstream
removed: based replication row
Revision history for this message
Sveta Smirnova (svetasmirnova) wrote :

Thank you for the report.

Verified as described.

Changed in percona-server:
status: New → Confirmed
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Is there an upstream bug report?

Revision history for this message
Sveta Smirnova (svetasmirnova) wrote :

Version 5.6 is not affected.

tags: added: regression
Revision history for this message
Sveta Smirnova (svetasmirnova) wrote :

Sorry, wrong binary log format with 5.6: affected as well.

tags: removed: regression
Revision history for this message
Sveta Smirnova (svetasmirnova) wrote :
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1784

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.