MySQL Bugs: #76872: InnoDB AUTO_INCREMENT produces same value twice

Bug #76872	InnoDB AUTO_INCREMENT produces same value twice
Submitted:	28 Apr 2015 14:51	Modified:	26 Aug 2016 19:13
Reporter:	Mattias Öhrn	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.6.24, 5.6.26	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
When more than one INSERT is executed concurrently on a non-empty InnoDB table with an AUTO_INCREMENT PK immediately after MySQL start up (before any other INSERTs on the same table) one will often fail with the message like "Duplicate entry '123' for key 'PRIMARY'".
This will only happen if innodb_autoinc_lock_mode is 1 or 2 and auto_increment_increment > 1.

How to repeat:
1. Create a table as follows:
CREATE TABLE `test` (
  `test_id` int(11) NOT NULL AUTO_INCREMENT,
  `testcol` varchar(256) COLLATE utf8_bin NOT NULL,
  PRIMARY KEY (`test_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin;

2. Insert one row as follows:
INSERT INTO `test` (`testcol`) VALUES ('aldsldjfhasjk');

3. Restart MySQL server (which has innodb_autoinc_lock_mode=1 and auto_increment_increment=2 configured).

4. Create two clients that connect to the MySQL server in parallel and await each other after this is completed.

5. Simultaneously execute one INSERT from each one of the clients.
INSERT INTO `test` (`testcol`) VALUES ('aldsldjfhasjk');

Result: One succeeds and one fails with the error message "Duplicate entry '123' for key 'PRIMARY'"

I am unable to repeat the bug. 

Can you elaborate on how do you succeed to run both commands simultaneously ???

Can you also send relevant InnoDB settings from your configuration file or from the arguments ???

Thanks in advance.

Output from SHOW GLOBAL VARIABLES

Attachment: global_vars.txt (text/plain), 12.91 KiB.

The configuration I use to reproduce the problem

Attachment: my.ini (application/octet-stream, text), 1.28 KiB.

.Net/C# project that can be used to reproduce the problem

Attachment: MySqlAutoIncrBug.zip (application/octet-stream, text), 4.57 KiB.

To execute multiple inserts simultaneously you can use an application that spin of multiple threads where each thread open a connection, then wait for all other threads using a synchronization primitive (System.Threading.Barrier is a suitable one in .Net) and then finally executes the INSERT. Note, that to reproduce the bug this MUST happen after a MySQL server restart, i.e. firt create the table and insert at least one row, then restart MySQL, then spin of the threads.

According to my investigation the relevant settings are the ones I mentioned in the initial description; "innodb_autoinc_lock_mode > 0" and "auto_increment_increment > 1". However, I have now attached the output from "SHOW GLOBAL VARIABLES;" as well as the my.ini I used to reproduce the problem.

I have also attached the VS project for the little application that reliably reproduce the problem on my machine. Of course, you need Windows and Visual Studio 2013 to build and run the application but if that's not an option the single source code file might provide some guidance on how to reproduce the problem anyway.

I managed to repeat your results. Hence, this bug is verified. However, since it is only one command that is missed and there are really no duplicate values in the auto-increment column I do not consider this bug a critical one. It is however, somewhere between S2 and S3, as one command is lost, so this still remains to be decided.

I used your test case 100 % regarding creation of table and one row insertion, while only changing your table name to `t3`, due to my own testing environment.

Here are the outputs of the relevant commands:

./client/mysql bug -e "select * from t3"
+---------+---------------+
| test_id | testcol       |
+---------+---------------+
|       1 | aldsldjfhasjk |
+---------+---------------+

and then I used this nifty and smart bash command to run INSERT statements in parallel:

 for i in {1..5}; do echo "INSERT INTO bug.t3 (testcol) VALUES ('aldsldjfhasjk')" | ./client/mysql > /dev/null & done

and have got the following output:

 ERROR 1062 (23000) at line 1: Duplicate entry '3' for key 'PRIMARY'

[1]   Done                    echo "INSERT INTO bug.t3 (testcol) VALUES ('aldsldjfhasjk')" | ./client/mysql > /dev/null
[2]   Done                    echo "INSERT INTO bug.t3 (testcol) VALUES ('aldsldjfhasjk')" | ./client/mysql > /dev/null
[3]   Done                    echo "INSERT INTO bug.t3 (testcol) VALUES ('aldsldjfhasjk')" | ./client/mysql > /dev/null
[4]-  Done                    echo "INSERT INTO bug.t3 (testcol) VALUES ('aldsldjfhasjk')" | ./client/mysql > /dev/null
[5]+  Exit 1                  echo "INSERT INTO bug.t3 (testcol) VALUES ('aldsldjfhasjk')" | ./client/mysql > /dev/null

with the final contents missing one row:

 ./client/mysql bug -e "select * from t3"
+---------+---------------+
| test_id | testcol       |
+---------+---------------+
|       1 | aldsldjfhasjk |
|       3 | aldsldjfhasjk |
|       5 | aldsldjfhasjk |
|       7 | aldsldjfhasjk |
|       9 | aldsldjfhasjk |
+---------+---------------+

Hence, the bug is verified.

We are experiencing this issue in production with servers with long uptime starting sometime in 5.5 and now in 5.6.24. It is far more prevalent in 5.6.24. Falling back to innodb_autoinc_lock_mode=0 or retrying the insert is the current work around.

Please consider raising this to an S2 severity as this is happening fairly frequently in our infrastructure. This has occurred over 700 times on one of many tables in the last 18 hours since we started monitoring this issue more closely.

I agree with you ... One lost command is not negligible.

This does not require a server restart to reproduce, here's a non-deterministic testcase that fails pretty much 100% on my system:

--source include/have_innodb.inc

# Should be != 0
SELECT @@innodb_autoinc_lock_mode;

CREATE TABLE `test` (
  `test_id` int(11) NOT NULL AUTO_INCREMENT PRIMARY KEY,
  `testcol` varchar(256)
) ENGINE=InnoDB;

INSERT INTO `test` (`testcol`) VALUES ('aldsldjfhasjk');

SET SESSION auto_increment_increment = 2;
send INSERT INTO `test` (`testcol`) VALUES ('aldsldjfhasjk');
--connect(con1,localhost,root,,)
--connection con1
SET SESSION auto_increment_increment = 2;
send INSERT INTO `test` (`testcol`) VALUES ('aldsldjfhasjk');
# --error 0,1062
reap;
--disconnect con1
--connection default
# --error 0,1062
reap;

SELECT * FROM test;

DROP TABLE test;

The issue is ha_innobase::get_auto_increment not honoring offset / increment for the 1st insert after setting the auto_increment_increment. In this example it returns 2 instead of 3, and sets 3 as the next auto increment value for the table. The caller handler::update_auto_increment then bumps the value to 3 itself, by the "nr= compute_next_insert_id(nr-1, variables)" hack, starting the window when the next insert will encounter the duplicate key error. The window is closed at the end of ha_innobase::write_row, which finds that the actual inserted value stepped out of the reserved interval, and updates the table autoinc value.

The fix appears to be push the effect of "nr= compute_next_insert_id(nr-1, variables)" to ha_innobase::get_auto_increment itself.

Thank you, Laurinas, for your comments.

This bug is already fully verified and has received relatively high priority in the in the process that follows. Also, your remarks have been passed to the developers.

Bug #78356 marked as duplicate of this.

Posted by developer:
 
Fixed as of the upcoming 5.6.34, 5.7.16, 8.0.1 release, and here's the changelog entry:

After a server restart, concurrent INSERT operations a table with an
auto-increment primary key resulted in a duplicate entry error. The
current auto-increment value was not changed after
auto_increment_increment and auto_increment_offset settings were modified.

Thank you for the bug report.

Posted by developer:
 
Changelog entry moved to 5.6.35, 5.7.17, 8.0.1 releases.

I'm still seeing this issue with version 5.6.35 FreeBSD 10.3 and can reproduce it with the above testing methodology.  Can someone open this ticket back up or do I have to open a new one?

https://dba.stackexchange.com/questions/190203/duplicate-error-after-truncation-for-innodb... shows the same(?) problem in 5.7.17 after a TRUNCATE TABLE.

https://dba.stackexchange.com/questions/190203/duplicate-error-after-truncation-for-innodb... shows the same(?) problem in 5.7.17 after a TRUNCATE TABLE.

Rick,

since scenario in this case is different I think it makes sense to open new bug report.

Also, please see related Bug #88321