MySQL Bugs: #35602: "Failed to read auto-increment value from storage engine" with Innodb

Bug #35602	"Failed to read auto-increment value from storage engine" with Innodb
Submitted:	27 Mar 2008 12:27	Modified:	30 Apr 2012 12:41
Reporter:	Philip Stoev	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.1,6.0	OS:	Any
Assigned to:	Sunny Bains	CPU Architecture:	Any

Description:
A relatively simple and valid scenario containing insert/replace/update results in 1467: Failed to read auto-increment value from storage engine, when using Innodb table.

How to repeat:
A test case will hopefully follow shortly.

Test case for bug #35602

Attachment: bug35602.zip (application/x-zip-compressed, text), 1.40 KiB.

To reproduce, please place the .txt files in mysql-test and the .test files in mysql-test/t. Then run:

$ perl ./mysql-test-run.pl --stress --stress-init-file=bug35602_init.txt \
--stress-test-file=bug35602_run.txt --stress-threads=20 --skip-ndb \
--mysql=--innodb --stress-test-duration=65535 \
--mysqld=--falcon-consistent-read=off \
--mysqld=--innodb_lock_wait_timeout=1 --mysqld=--falcon_lock_wait_timeout=1

Let it run for 5 minutes, ignore the output the test sends to the console. Instead, please go to mysql-test/var/stress, grep for "increment" in that directory and you will see the offending error message. Any other error messages about deadlocks and timeouts are dealt in separate bugs.

Please note that the table that reports the failure is view2/inter2, which is the Innodb table.

Please accept my apologies for not simplifying the test further, after several hours I was unable to progress further than that. If further simplification is required to fix the bug, I will spend extra time on it.

Yes this bug is present in the latest mysql-6.0 BK tree.

Assigned to our autoinc expert.

Philip,

Thanks for the test case. In your comment about the bug you say:
"
A relatively simple and valid scenario containing insert/replace/update
results in 1467:Failed to read auto-increment value from storage engine,
when using Innodb table.
"

Is this for a single thread or multiple threads ? For a single thread it would
certainly be an error. But for the case of multiple threads not so, there are
two runtime scenarios here:

 1.If multiple threads try and initialize the auto-inc counter
from the table only one should succeed and others should fail. This should
happen only once since the auto-inc counter is initialized only once.

 2. For old style autolocking there can be both deadlock and lock timeout errors
and that's OK too. Old style locking a.k.a. "traditional" autolock mode uses database locking and that can cause these errors. The newer locking modes use mutexes and shouldn't result in these errors.

I've been running your multiple threads test and haven't seen any errors so far though if it's one of the above they are not really errors.

Regards,
-sunny

A few more observations:

* Multiple threads are involved.

* Initially the test does not produce any errors, however after running it for a while (20 min), the errors accumulated start growing steadily and into the thousands. In other words, there is more than one error per thread and it does not happen on test startup.

* The rest of the errors, e.g. deadlocks and timeouts, relate to a separate bug #35321.

* I think this error is insufficiently documented to say that it is OK to observe it frequently. I would vote that we either document the error and say that it is OK to have it, or protect the auto-increment counter (intialization) with a mutex in order to avoid having it at all.

Verified as described.

Sunny, Philip, I hit this bug too, and made a simplified testcase, attached.

Attachment: bug35602.c (text/plain), 7.10 KiB.

The attached testcase from me gives the error on 5.1.24.

[sbester@box1 ~]$ ./bug35602 
running initializations..
client version=50125
server version=50124
about to spawn 5 threads
.....
completed spawning new database worker threads
testcase is now running, so watch for error output
<cut>
query failed 'delete from `qa05` where `d` in ('99','-54','105')' : 1213 (Deadlock found when trying to get lock; try restarting transaction)
query failed 'replace into `qa05` (`d`) values ('13')' : 1213 (Deadlock found when trying to get lock; try restarting transaction)
query failed 'insert into `qa05` (`d`) values ('-31')' : 1213 (Deadlock found when trying to get lock; try restarting transaction)
query failed 'insert into `qa05` (`d`) values ('-49')' : 1467 (Failed to read auto-increment value from storage engine)
queries: 000013120
query failed 'replace into `qa05` (`d`) values ('36')' : 1467 (Failed to read auto-increment value from storage engine)
q

The problem for the autoinc read error is due to this code in
ha_innobase::innobase_autoinc_lock(void) (ha_innodb.cc):

                /* For simple (single/multi) row INSERTs, we fallback to the
                old style only if another transaction has already acquired
                the AUTOINC lock on behalf of a LOAD FILE or INSERT ... SELECT
                etc. type of statement. */
                if (thd_sql_command(user_thd) == SQLCOM_INSERT) {

We are not checking for SQLCOM_REPLACE therefore the replace statements are
falling back to the old style locking, this results in dead lock errors. The
simple fix is to add SQLCOM_REPLACE to the condition. I need to confirm whether
this is simply an oversight or not. I think it's an oversight because REPLACE
is classified as a "simple INSERT" in the documentation. However can someone
please check this fix (below) with replication because thats' the only
complication and the (only) reason for the special AUTOINC lock.

                /* For simple (single/multi) row INSERTs, we fallback to the
                old style only if another transaction has already acquired
                the AUTOINC lock on behalf of a LOAD FILE or INSERT ... SELECT
                etc. type of statement. */
                if (thd_sql_command(user_thd) == SQLCOM_INSERT
                    || thd_sql_command(user_thd) == SQLCOM_REPLACE) {
      
Regards,
-sunny

Sunny,

Your fix seems to work great. Using Shane's test case I don't get the error anymore.
I used mysql-5.1 from latest source tree. So we'll have to push this there too, hopefully.

However you decide to handle this is ok with us.  We are doing some last-minute testing to be sure there are no issues w.r.t. replication, but we expect none.  I repeat that (from our viewpoint) this seems to be a low-risk fix that can be introduced in a release after 5.1.25.  We also don't think it is necessary or appropriate to hold 5.1.25 back waiting for this fix.

I do want to clarify/correct Jeff's comment above: "the low incidence (will only affect new customers using the feature)".  I don't claim to know anything about the incidence of this issue, but because the "problem" exists in the old code, it does not affect only new customers, and does not involve a new feature.  This affects users of the REPLACE command when AUTOINC is involved, and the same behavior existed in 5.0.  Thus, this entire issue is not a regression from 5.0.

What we have is a fix for the NEW algorithm introduced in 5.1.22.  Since 5.1.22, the NEW algorithm (which is the default) does not handle REPLACE like it does other INSERT-like statements.  Therefore the behavior reverts to the old behavior for REPLACE (regardless of the setting for innodb_autoinc_lock_mode).  So, the fix at hand would be helpful for users of the REPLACE command, but not applying the fix does not result in a regression.

Hope this helps.

Merged into 6.0.6-alpha, according to Tim. But the patch has not been pushed into 5.1 yet.

This has been queued into the mysql-5.1-bugteam tree, and will be pushed to main along with the other SR51SP bugs.  Docs: please return to Patch Queued or NDI once documented for 6.0.

Hmm ... the bug report doesn't seem to actually say what the problem *is*. There are vague allusions to it, but no explicit statement. What should the changelog entry say? Thanks.

Paul,

The fix makes REPLACE work the same way as other "simple inserts" instead of
using the old locking algorithm. Before the fix REPLACE statements would fall
back to using the "traditional" style locking. With this fix REPLACE statements
are treated in the same way as as INSERT statements.

Regards,
-sunny

Noted in 6.0.6 changelog.

Setting report to Need Doc Info pending push of fix into 5.1.x.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/52004

2714 Timothy Smith	2008-08-19
      Cherry-pick one change from innodb-5.1-ss2485 snapshot.  Fixes Bug#35602.
      
      Bug #35602 "Failed to read auto-increment value from storage engine" with
      Innodb
      
      The test for REPLACE was an error of ommission since it's classified as
      a simple INSERT. For REPLACE statements we don't acquire the special
      AUTOINC lock for AUTOINC_NEW_STYLE_LOCKING with this fix.

Pushed into 5.1.28  (revid:timothy.smith@sun.com-20080820004056-g05a56h7y8n0zczb) (version source revid:azundris@mysql.com-20080821081500-f2d61fh4u61owz3p) (pib:3)

Noted in 5.1.28 changelog.

Pushed into 6.0.7-alpha  (revid:timothy.smith@sun.com-20080820004056-g05a56h7y8n0zczb) (version source revid:sven@mysql.com-20080818195835-r615g9zz6xphmkzg) (pib:3)

sunny, should SQLCOM_INSERT_SELECT also have been handled ?

Hello,

This bug is not at all fixed. I am running 5.5.2 64 bit here (innodb) and the bug occurs after an insert in the db trying to fetch the autonumber generated by that insert (if would love to have that autonumber returened with an .update!!).

Note that I execute a requery in between, to make sure that the new record is fetched.

I noticed that the bug temporairely dissapears after truncating the related table.

Sincerely,

Louis

Setting back to verified so that the Inndb people provide feedback on the last two comments.

Hi Louis,

Please post the exact SQL statements that reproduce the reported error
and I will investigate.

Regards,
-sunny

I'm getting this same error.

I'm using HeidiSQL to connect to my database (version 5.1.41):

SELECT VERSION() ;
SHOW STATUS LIKE 'Uptime' ;
SHOW DATABASES ;
USE `nreservices` ;
SHOW TABLES FROM `information_schema` ;
(SELECT TABLE_NAME AS `Name`, TABLE_TYPE AS `Type`, ENGINE AS `Engine`, VERSION AS `Version`, ROW_FORMAT AS `Row_format`, TABLE_ROWS AS `Rows`, AVG_ROW_LENGTH AS `Avg_row_length`, DATA_LENGTH AS `Data_length`, MAX_DATA_LENGTH AS `Max_data_length`, INDEX_LENGTH AS `Index_length`, DATA_FREE AS `Data_free`, AUTO_INCREMENT AS `Auto_increment`, CREATE_TIME AS `Create_time`, UPDATE_TIME AS `Update_time`, CHECK_TIME AS `Check_time`, TABLE_COLLATION AS `Collation`, CHECKSUM AS `Checksum`, CREATE_OPTIONS AS `Create_options`, TABLE_COMMENT AS `Comment` FROM `information_schema`.TABLES WHERE TABLE_SCHEMA = 'nreservices') UNION (SELECT ROUTINE_NAME AS `Name`, ROUTINE_TYPE AS `Type`, NULL AS `Engine`, NULL AS `Version`, NULL AS `Row_format`, NULL AS `Rows`, NULL AS `Avg_row_length`, NULL AS `Data_length`, NULL AS `Max_data_length`, NULL AS `Index_length`, NULL AS `Data_free`, NULL AS `Auto_increment`, CREATED AS `Create_time`, LAST_ALTERED AS `Update_time`, NULL AS `Check_time`, NULL AS `Collation`, NULL AS `Checksum`, NULL AS `Create_options`, ROUTINE_COMMENT AS `Comment` FROM `information_schema`.ROUTINES WHERE ROUTINE_SCHEMA = 'nreservices') ORDER BY `Name` ;
SHOW /*!32332 FULL */ COLUMNS FROM `tocs_thirdparties` ;
SHOW KEYS FROM `tocs_thirdparties` ;
SELECT `clientid`, LEFT(`clientname`, 256) FROM `nreservices`.`tocs_thirdparties` LIMIT 0, 1000 ;
INSERT INTO `nreservices`.`tocs_thirdparties` (`clientname`) VALUES ('Eurostar') ;
/* SQL Error: Failed to read auto-increment value from storage engine */
INSERT INTO `nreservices`.`tocs_thirdparties` (`clientname`) VALUES ('Eurostar') ;
/* SQL Error: Failed to read auto-increment value from storage engine */
INSERT INTO `nreservices`.`tocs_thirdparties` (`clientname`) VALUES ('Eurostar') ;
/* SQL Error: Failed to read auto-increment value from storage engine */

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

Keeping this bug open.

Kathryn,

Thank you for the feedback. Please also provide output of SHOW CREATE TABLE nreservices and dump of table nreservices (you can download it on our FTP server as described in "Files" tab of the bug report interface)

Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

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

Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

I'm usin mysql 5.1.41 and have the same eror when i restored a backup. The primary key auto increment had a value 18453112315648951 mi field was unsigned int zero fil. 
I changed this wrong value to other and solve this problem.
Sorry for my english.
Thaks

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

I have this problem with INSERT .. SELECT:
mysql> insert into dim_flights select distinct uniquecarrier,airlineid,carrier,TailNum,FlightNum,null from ontime;
ERROR 1467 (HY000): Failed to read auto-increment value from storage engine

mysql> show create table dim_flights\G
*************************** 1. row ***************************
       Table: dim_flights
Create Table: CREATE TABLE `dim_flights` (
  `UniqueCarrier` varchar(10) DEFAULT NULL,
  `AirlineID` varchar(10) DEFAULT NULL,
  `Carrier` varchar(10) DEFAULT NULL,
  `TailNum` varchar(20) DEFAULT NULL,
  `FlightNum` varchar(10) DEFAULT NULL,
  `carrier_id` tinyint(4) NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (`carrier_id`)
) ENGINE=InnoDB AUTO_INCREMENT=127 DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> show create table ontime\G
*************************** 1. row ***************************
       Table: ontime
Create Table: CREATE TABLE `ontime` (
 ...
  `UniqueCarrier` varchar(10) DEFAULT NULL COMMENT 'Unique Carrier Code. When the same code has been used by multiple carriers, a numeric suffix is used for earlier users, for example, PA, PA(1), PA(2). Use this field for analysis across a range of years.',
  `AirlineID` varchar(10) DEFAULT NULL COMMENT 'An identification number assigned by US DOT to identify a unique airline (carrier). A unique airline (carrier) is defined as one holding and reporting under the same DOT certificate regardless of its Code, Name, or holding company/corporation.',
  `Carrier` varchar(10) DEFAULT NULL COMMENT 'Code assigned by IATA and commonly used to identify a carrier. As the same code may have been assigned to different carriers over time, the code is not always unique. For analysis, use the Unique Carrier Code.',
  `TailNum` varchar(20) DEFAULT NULL COMMENT 'Tail Number',
  `FlightNum` varchar(10) DEFAULT NULL COMMENT 'Flight Number'
...
) engine=innodb;

The table is partitioned by range on year.

Data is available from BTS:
http://www.transtats.bts.gov/Download/On_Time_On_Time_Performance_1987_10.zip
http://www.transtats.bts.gov/Download/On_Time_On_Time_Performance_1987_11.zip
http://www.transtats.bts.gov/Download/On_Time_On_Time_Performance_1987_12.zip
...
http://www.transtats.bts.gov/Download/On_Time_On_Time_Performance_1991_1.zip

I can give you full DDL for the ontime table if you want. It was too long for the comment system.

this bug has been fixed for 3.5 years.