Bug #71173 MySQL 5.7.3 InnoDB multiple errors: 'chsize' returned OS error 71
Submitted: 18 Dec 2013 14:57 Modified: 25 Feb 2014 17:55
Reporter: Oscar González Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.7.3 OS:Windows (Windows 7 Enterprise 64-bit)
Assigned to: CPU Architecture:Any
Tags: 5.7.3, chsize, error log, innodb, OS error 71, truncate

[18 Dec 2013 14:57] Oscar González
Description:
InnoDB started reporting multiple errors on error-log for "TRUNCATE table":

(Extract from error log)
2013-12-17 20:45:24 0x1d74  InnoDB: Operating system error number 2 in a file operation.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2013-12-18T01:45:24.762856Z 498 [ERROR] InnoDB: File .\comcel\oss_3g_softho_tmp.ibd: 'chsize' returned OS error 71.
2013-12-18T01:45:24.764856Z 498 [ERROR] InnoDB: Cannot truncate file .\comcel\oss_3g_softho_tmp.ibd in TRUNCATE TABLESPACE.
2013-12-17 20:45:28 0x1d74  InnoDB: Operating system error number 2 in a file operation.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2013-12-18T01:45:28.931272Z 498 [ERROR] InnoDB: File .\comcel\oss_3g_celltp_tmp.ibd: 'chsize' returned OS error 71.
2013-12-18T01:45:28.932272Z 498 [ERROR] InnoDB: Cannot truncate file .\comcel\oss_3g_celltp_tmp.ibd in TRUNCATE TABLESPACE.
2013-12-17 20:45:34 0x1d74  InnoDB: Operating system error number 2 in a file operation.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2013-12-18T01:45:34.337813Z 498 [ERROR] InnoDB: File .\comcel\oss_3g_pktcall_tmp.ibd: 'chsize' returned OS error 71.
2013-12-18T01:45:34.338813Z 498 [ERROR] InnoDB: Cannot truncate file .\comcel\oss_3g_pktcall_tmp.ibd in TRUNCATE TABLESPACE.
2013-12-17 20:45:40 0x1d74  InnoDB: Operating system error number 2 in a file operation.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2013-12-18T01:45:40.480427Z 498 [ERROR] InnoDB: File .\comcel\oss_3g_hsdpaw_tmp.ibd: 'chsize' returned OS error 71.
2013-12-18T01:45:40.482427Z 498 [ERROR] InnoDB: Cannot truncate file .\comcel\oss_3g_hsdpaw_tmp.ibd in TRUNCATE TABLESPACE.
2013-12-17 20:45:44 0x1d74  InnoDB: Operating system error number 2 in a file operation.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2013-12-18T01:45:44.987878Z 498 [ERROR] InnoDB: File .\comcel\oss_3g_intsysho_tmp.ibd: 'chsize' returned OS error 71.
2013-12-18T01:45:44.988878Z 498 [ERROR] InnoDB: Cannot truncate file .\comcel\oss_3g_intsysho_tmp.ibd in TRUNCATE TABLESPACE.
2013-12-17 20:45:48 0x1d74  InnoDB: Operating system error number 2 in a file operation.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2013-12-18T01:45:48.939273Z 498 [ERROR] InnoDB: File .\comcel\oss_3g_intersho_tmp.ibd: 'chsize' returned OS error 71.
2013-12-18T01:45:48.940273Z 498 [ERROR] InnoDB: Cannot truncate file .\comcel\oss_3g_intersho_tmp.ibd in TRUNCATE TABLESPACE.
(Extract from error log)

This problem started after migration of DB from MySQL 5.6.10 to 5.7.3.

Migration process was normal. Dumped all tables with mysqldump. Uninstalled MySQL 5.6.10. Downloaded and Installed MySQL 5.7.3 Windows Installer (MSI). Changed few values on my.ini. Started MySQL 5.7.3 and imported all tables back again with mysql command. So far so good...

Then after fully restored my DB, I started my application (VB.NET). This app loads about 150-200 CSV data files into InnoDB tables, every hour, using "LOAD DATA LOCAL INFILE" after previous "TRUNCATE table" command (First "TRUNCATE" the table, then "LOAD DATA LOCAL INFILE" to load it with CSV-file's contents)

First 8 hours of operation went OK, but then multiple errors started popping up when the app tried to TRUNCATE the tables, prior to loading data on them, getting a "Got error -1 from storage engine" message from MySQL:

(Extract of app's log)
* 18/12/2013 02:00:00 a.m. - oss_3g_softho_tmp: Got error -1 from storage engine
* 18/12/2013 02:00:00 a.m. - oss_3g_celltp_tmp: Got error -1 from storage engine
* 18/12/2013 02:00:00 a.m. - oss_3g_pktcall_tmp: Got error -1 from storage engine
* 18/12/2013 02:00:00 a.m. - oss_3g_hsdpaw_tmp: Got error -1 from storage engine
* 18/12/2013 02:00:00 a.m. - oss_3g_intsysho_tmp: Got error -1 from storage engine
* 18/12/2013 02:00:00 a.m. - oss_3g_intersho_tmp: Got error -1 from storage engine
(Extract of app's log)

How to repeat:
This one is very difficult to repeat, because I'm unable to determine if the problems starts after a specific number of TRUNCATE operations, or after a specific number of files opened, or after a specific time after the MySQL started

Suggested fix:
The problem was fixed (at least for a moment) when I stopped and restarted the MySQL service (mysqld). After restarted, TRUNCATE operations went OK, but a few hours later the "Got error -1 from storage engine" message started showing up again.
[23 Dec 2013 14:00] Oscar González
Hello guys!

Any news?
[27 Jan 2014 15:07] Oscar González
Hello again,

Is anybody going to take a look at this, or maybe not?

Thanks,
OscarG.
[27 Jan 2014 19:30] MySQL Verification Team
I'm guessing the error is that _open_osfhandle fails.  The limit of C runtime file descriptors is 2048 minus a few for already open files.  I will try repeat this by creating >2048 innodb tables with large enough table cache... and truncate them all
[3 Feb 2014 13:20] MySQL Verification Team
Today I spontaneously encountered this error.

Version: '5.7.4-m14'  socket: ''  port: 3306  MySQL Community Server (GPL)
2014-02-03T13:19:05.262278Z 1 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2014-02-03T13:19:05.262778Z 1 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2014-02-03T13:19:05.262778Z 1 [ERROR] InnoDB: File .\test\blobtest_4.ibd: 'chsize' returned OS error 71.
2014-02-03T13:19:05.262778Z 1 [ERROR] InnoDB: Cannot truncate file .\test\blobtest_4.ibd in TRUNCATE TABLESPACE.
2014-02-03T13:19:05.267779Z 3 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2014-02-03T13:19:05.268279Z 3 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2014-02-03T13:19:05.268279Z 3 [ERROR] InnoDB: File .\test\blobtest_3.ibd: 'chsize' returned OS error 71.
2014-02-03T13:19:05.268279Z 3 [ERROR] InnoDB: Cannot truncate file .\test\blobtest_3.ibd in TRUNCATE TABLESPACE.
2014-02-03T13:19:05.279280Z 2 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2014-02-03T13:19:05.279280Z 2 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2014-02-03T13:19:05.279780Z 2 [ERROR] InnoDB: File .\test\blobtest_3.ibd: 'chsize' returned OS error 71.
2014-02-03T13:19:05.279780Z 2 [ERROR] InnoDB: Cannot truncate file .\test\blobtest_3.ibd in TRUNCATE TABLESPACE.
2014-02-03T13:19:05.292782Z 3 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2014-02-03T13:19:05.293282Z 3 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2014-02-03T13:19:05.293282Z 3 [ERROR] InnoDB: File .\test\blobtest_5.ibd: 'chsize' returned OS error 71.
2014-02-03T13:19:05.293282Z 3 [ERROR] InnoDB: Cannot truncate file .\test\blobtest_5.ibd in TRUNCATE TABLESPACE.
2014-02-03T13:19:05.327286Z 1 [ERROR] InnoDB: Operating system error number 2 in a file operation.
[3 Feb 2014 13:34] MySQL Verification Team
The handle from _open_osfhandle is not being closed in os_file_truncate!
[3 Feb 2014 16:45] MySQL Verification Team
Seems hard to repeat this again. All I have now is ever-increasing "handles" according to task manager. But no more errors... I'll leave it running longer.
[3 Feb 2014 18:04] MySQL Verification Team
The problem is two-fold.

_open_osfhandle is failing and we don't check for that.
The actual error from that CRT function is this:

if ( (fh = _alloc_osfhnd()) == -1 ) {
       errno = EMFILE;         /* too many open files */
      _doserrno = 0L;         /* not an OS error */
      return -1;              /* return error to caller */
}

So on a debug build, we get CRT assertion as expected:

Version: '5.7.4-m14-debug'  socket: ''  port: 3306  MySQL Community Server (GPL)
f:\dd\vctools\crt_bld\self_64_amd64\crt\src\chsize.c(55) : Assertion failed: (filedes >= 0 && (unsigned)filedes < (unsigned)_nhandle)

Then, _chsize is receiving a fd of -1, which is invalid.

Testcase for windows:
---------------------

drop procedure if exists p1;
drop table if exists t1;
create table t1(a longblob)engine=innodb;
delimiter $
create procedure p1()
begin  repeat 
truncate t1; insert into t1 values (repeat('a',1000000));
until 1=2 end repeat; end $
delimiter ;
call p1(); #run in two threads
[3 Feb 2014 18:08] MySQL Verification Team
I'd think we shouldn't be using c runtime file descriptors/functions such as _open_osfhandle anymore.  but I don't know an easy Win32 API replacement to _chsize!
[25 Feb 2014 18:29] MySQL Verification Team
Fixed as of 5.7.4, and here's the changelog entry:

"TRUCATE TABLE" on Windows would report multiple "'chsize' returned OS
error 71" errors.

Thank you for the bug report.