Bug #83218 DML operations in multiple sessions fail
Submitted: 30 Sep 2016 7:26 Modified: 17 Mar 2017 11:26
Reporter: Johanna Välimäki Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Group Replication Severity:S2 (Serious)
Version:5.7.15-labs, 5.7.17 OS:Red Hat
Assigned to: Nuno Carvalho CPU Architecture:Any
Tags: group_replication

[30 Sep 2016 7:26] Johanna Välimäki
Description:
The environment contains three database nodes with group replication setup. I'm trying to load the database with some operations. Basically there are transactions in a loop, and a transaction does few reads, inserts and updates. The operations all go to a same database node.

When there are multiple sessions, every now and then a transaction is aborted with an error message: ERROR 3101 (HY000): Plugin instructed the server to rollback the current transaction.

How to repeat:
Situation was repeatable with our application with multiple sessions. But it was also repeatable with two SQL client sessions to a same database instance executing a stored procedure inserting data in a loop to a database table.

Tested with MySQL labs version 5.7-14 and 5.7-15.
[30 Sep 2016 14:18] Nuno Carvalho
Hi Johanna,

Thank you for your bug report, though we need more information in order to analyse it.
Can you please write down the schema, queries and a execution trace so that we can reproduce it deterministically?

Best regards,
Nuno Carvalho
[1 Nov 2016 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".
[27 Jan 2017 17:39] Chris Lee
i can provide how to reproduce everytime by following steps.

1) start three mysql-gr nodes with docker, by following command.

docker-clean stop && \
docker network create group1 && \
docker run -d \
--name=node1 --net=group1 \
-e MYSQL_ROOT_PASSWORD=aTestPwd \
-e MYSQL_REPLICATION_USER=rpl_user \
-e MYSQL_REPLICATION_PASSWORD=rpl_pass \
-p 3306:3306 \
mysql/mysql-gr \
--group_replication_group_seeds='node2:6606,node3:6606' \
--server-id=1 && \
sleep 2 && \
docker run -d \
--name=node2 --net=group1 \
-e MYSQL_ROOT_PASSWORD=aTestPwd \
-e MYSQL_REPLICATION_USER=rpl_user \
-e MYSQL_REPLICATION_PASSWORD=rpl_pass \
-p 3307:3306 \
mysql/mysql-gr \
--group_replication_group_seeds='node1:6606,node3:6606' \
--server-id=2 && \
sleep 2 && \
docker run -d \
--name=node3 --net=group1 \
-e MYSQL_ROOT_PASSWORD=aTestPwd \
-e MYSQL_REPLICATION_USER=rpl_user \
-e MYSQL_REPLICATION_PASSWORD=rpl_pass \
-p 3308:3306 \
mysql/mysql-gr \
--group_replication_group_seeds='node1:6606,node2:6606' \
--server-id=3

2) create test database named "repl_test"
CREATE DATABASE `repl_test` /*!40100 DEFAULT CHARACTER SET utf8 */

3) using percona sysbench docker image to prepare data.

docker run --rm -it --net=group1 \
percona/sysbench \
-c '/opt/sysbench/sysbench \
--test=oltp \
--db-driver=mysql \
--mysql-engine-trx=yes \
--mysql-table-engine=innodb \
--mysql-host=node1 \
--mysql-user=root \
--mysql-password=aTestPwd \
--mysql-db=repl_test \
--oltp-auto-inc=on \
--test=/opt/tests/db/oltp.lua \
--oltp-table-size=5000 \
--oltp-tables-count=8 \
prepare'

4) using sysbench to do update query with node1.

docker run --rm -it --net=group1 \
percona/sysbench \
-c '/opt/sysbench/sysbench \
--test=oltp \
--db-driver=mysql \
--mysql-table-engine=innodb \
--mysql-host=node1 \
--mysql-user=root \
--mysql-password=aTestPwd \
--mysql-db=repl_test \
--test=/opt/tests/db/update_index.lua \
--oltp-table-size=5000 \
--oltp-tables-count=8 \
--num-threads=8 \
--report-interval=1 \
--max-requests=10000 \
run'

5) using sysbench to do update query with node2.

docker run --rm -it --net=group1 \
percona/sysbench \
-c '/opt/sysbench/sysbench \
--test=oltp \
--db-driver=mysql \
--mysql-table-engine=innodb \
--mysql-host=node2 \
--mysql-user=root \
--mysql-password=aTestPwd \
--mysql-db=repl_test \
--test=/opt/tests/db/update_index.lua \
--oltp-table-size=5000 \
--oltp-tables-count=8 \
--num-threads=8 \
--report-interval=1 \
--max-requests=10000 \
run'

6) then you should see the sql error. "

ALERT: mysql_drv_query() for query 'UPDATE sbtest1 SET k=k+1 WHERE id=xxx' failed: 3101 Plugin instructed the server to rollback the current transaction.

7) but i can still sucess to run sysbench on node1.
[16 Feb 2017 12:53] Umesh Shastry
Thank you for the details.
[16 Feb 2017 12:58] Umesh Shastry
-- Setup GR, make sure there are more than one primary node in the GR

nod1> SELECT * FROM performance_schema.replication_group_members;
+---------------------------+--------------------------------------+-------------+-------------+--------------+
| CHANNEL_NAME              | MEMBER_ID                            | MEMBER_HOST | MEMBER_PORT | MEMBER_STATE |
+---------------------------+--------------------------------------+-------------+-------------+--------------+
| group_replication_applier | 2412f46a-f446-11e6-baa9-0010e05f3e06 | hod03       |        3306 | ONLINE       |
| group_replication_applier | 39882d2e-f446-11e6-9c9f-0010e05f4178 | hod04       |        3306 | ONLINE       |
| group_replication_applier | 3b3d8837-f446-11e6-b909-0010e0734b98 | hod06       |        3306 | ONLINE       |
+---------------------------+--------------------------------------+-------------+-------------+--------------+
3 rows in set (0.00 sec)

-- node 1 still running

[umshastr@hod03]~/bugs/sysbench1.0:   bin/sysbench  --max-requests=0 share/sysbench/oltp_update_index.lua --table_size=5000 --tables=8 --report-interval=3  --db-driver=mysql --mysql-user=root --mysql-db=test --mysql-socket=/tmp/mysql_hod03.sock prepare
[umshastr@hod03]~/bugs/sysbench1.0:   bin/sysbench  --max-requests=0 share/sysbench/oltp_update_index.lua --table_size=5000 --tables=8 --report-interval=3  --db-driver=mysql --mysql-user=root --mysql-db=test --mysql-socket=/tmp/mysql_hod03.sock prepare
sysbench 1.0.0 (using bundled LuaJIT 2.1.0-beta2)

Creating table 'sbtest1'...
Inserting 5000 records into 'sbtest1'
Creating secondary indexes on 'sbtest1'...
Creating table 'sbtest2'...
Inserting 5000 records into 'sbtest2'
Creating secondary indexes on 'sbtest2'...
Creating table 'sbtest3'...
Inserting 5000 records into 'sbtest3'
Creating secondary indexes on 'sbtest3'...
Creating table 'sbtest4'...
Inserting 5000 records into 'sbtest4'
Creating secondary indexes on 'sbtest4'...
Creating table 'sbtest5'...
Inserting 5000 records into 'sbtest5'
Creating secondary indexes on 'sbtest5'...
Creating table 'sbtest6'...
Inserting 5000 records into 'sbtest6'
Creating secondary indexes on 'sbtest6'...
Creating table 'sbtest7'...
Inserting 5000 records into 'sbtest7'
Creating secondary indexes on 'sbtest7'...
Creating table 'sbtest8'...
Inserting 5000 records into 'sbtest8'
Creating secondary indexes on 'sbtest8'...
[umshastr@hod03]~/bugs/sysbench1.0: bin/sysbench  --time=3600 --max-requests=0 share/sysbench/oltp_update_index.lua --table_size=5000 --tables=8 --report-interval=3  --db-driver=mysql --mysql-user=root --mysql-db=test --mysql-socket=/tmp/mysql_hod03.sock run
sysbench 1.0.0 (using bundled LuaJIT 2.1.0-beta2)

Running the test with following options:
Number of threads: 1
Report intermediate results every 3 second(s)
Initializing random number generator from current time

Initializing worker threads...

Threads started!

[ 3s ] thds: 1 tps: 5754.05 qps: 5754.05 (r/w/o: 0.00/772.76/4981.29) lat (ms,95%): 0.81 err/s: 0.00 reconn/s: 0.00
[ 6s ] thds: 1 tps: 4836.77 qps: 4836.77 (r/w/o: 0.00/627.72/4209.05) lat (ms,95%): 1.03 err/s: 0.00 reconn/s: 0.00
[ 9s ] thds: 1 tps: 4832.67 qps: 4832.67 (r/w/o: 0.00/636.00/4196.67) lat (ms,95%): 1.04 err/s: 0.00 reconn/s: 0.00

--node 2 failed

[umshastr@hod04]~/bugs/sysbench1.0: bin/sysbench  --time=3600 --max-requests=0 share/sysbench/oltp_update_index.lua --table_size=5000 --tables=8 --report-interval=3  --db-driver=mysql --mysql-user=root --mysql-db=test --mysql-socket=/tmp/mysql_hod04.sock run
sysbench 1.0.0 (using bundled LuaJIT 2.1.0-beta2)

Running the test with following options:
Number of threads: 1
Report intermediate results every 3 second(s)
Initializing random number generator from current time

Initializing worker threads...

Threads started!

FATAL: mysql_stmt_execute() returned error 3101 (Plugin instructed the server to rollback the current transaction.) for query 'UPDATE sbtest7 SET k=k+1 WHERE id=?'
FATAL: `thread_run' function failed: ...umshastr/bugs/sysbench1.0/share/sysbench/oltp_common.lua:447: SQL error, errno = 3101, state = 'HY000': Plugin instructed the server to rollback the current transaction.
Error in my_thread_global_end(): 1 threads didn't exit
[16 Feb 2017 13:08] Johanna Välimäki
Hi,

Just for everybody to know, that our case was discussed internally with MySQL as I could not reveal the code example in public. MySQL documentation has been updated to contain restrictions and we have changed our setup to single primary mode. 

Our issue is still possible to be reproduced in multi primary mode, so I suppose Chris has found the same problem.
[17 Mar 2017 11:26] David Moss
Posted by developer:
 
Thanks for your feedback. This was fixed in 5.7.17. A change log entry was not added as this behaviour was in a labs version.
[28 Apr 2017 12:58] Sheraz Ahmed
We are using MySQL 5.7.17 in production and facing the exact same issue in multi-master group replication mode (even though write operations happen only on one node). 

The situation is as follows: 

One service frequently insert rows into a table. For each insert a separate connection is established with database. Its a single threaded service. 

Another service fetch the records from database table, update them and saves them back. Again, its a single threaded service. 

Every now and then, the update operation results in the following error: "MySql.Data.MySqlClient.MySqlException (0x80004005): Plugin instructed the server to rollback the current transaction". 

I have read all the available documentation on group replication multiple times. There is absolutely no reason for this error to occur in the above mentioned situation at the best of my knowledge. 

The bug reported in this ticket explains similar scenario. Is this bug really fixed in MySQL 5.7.17?