[MDEV-12027] posix_fallocate returned OS error 201. Created: 2017-02-08  Updated: 2017-02-21  Resolved: 2017-02-16

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1.21
Fix Version/s: 10.1.22

Type: Bug Priority: Major
Reporter: Timofey Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None
Environment:

Debian 8, Kernel 4.9.2, Btrfs, innodb_use_fallocate=ON


Issue Links:
Duplicate
duplicates MDEV-12075 innodb_use_fallocate does not work in... Closed
Problem/Incident
is caused by MDEV-11556 InnoDB redo log apply fails to adjust... Closed

 Description   

Hi, after latest updates i get a strange error:
"posix_fallocate returned OS error 201."
After that mariadb just get crash and restart.

Full log:

Feb 08 16:39:17 mon-db mysqld[7389]: 2017-02-08 16:39:17 140038274472704 [ERROR] InnoDB: preallocating file space for file './zabbixproduction/#sql-ib540-2259362375.ibd' failed.  Current size 65536, desired size 65536
 
Feb 08 16:39:17 mon-db mysqld[7389]: 2017-02-08 16:39:17 7f5d339adb00  InnoDB: Operating system error number 1 in a file operation.
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: Error number 1 means 'Operation not permitted'.
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: Some operating system error numbers are described at
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
Feb 08 16:39:17 mon-db mysqld[7389]:  InnoDB: Operation posix_fallocate to file /home/buildbot/buildbot/build/mariadb-10.1.21/storage/xtradb/fil/fil0fil.cc and at line 1083
 
Feb 08 16:39:17 mon-db mysqld[7389]: 2017-02-08 16:39:17 140038274472704 [ERROR] InnoDB: File ./zabbixproduction/#sql-ib540-2259362375.ibd: 'posix_fallocate' returned OS error 201.
 
Feb 08 16:39:17 mon-db mysqld[7389]: 2017-02-08 16:39:17 7f5d339adb00  InnoDB: Assertion failure in thread 140038274472704 in file handler0alter.cc line 137
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: We intentionally generate a memory trap.
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: If you get repeated assertion failures or crashes, even
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: immediately after the mysqld startup, there may be
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: corruption in the InnoDB tablespace. Please refer to
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
Feb 08 16:39:17 mon-db mysqld[7389]: InnoDB: about forcing recovery.
 
Feb 08 16:39:17 mon-db mysqld[7389]: 170208 16:39:17 [ERROR] mysqld got signal 6 ;
 
Feb 08 16:39:17 mon-db mysqld[7389]: This could be because you hit a bug. It is also possible that this binary
 
Feb 08 16:39:17 mon-db mysqld[7389]: or one of the libraries it was linked against is corrupt, improperly built,
 
Feb 08 16:39:17 mon-db mysqld[7389]: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Feb 08 16:39:17 mon-db mysqld[7389]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
Feb 08 16:39:17 mon-db mysqld[7389]: We will try our best to scrape up some info that will hopefully help
 
Feb 08 16:39:17 mon-db mysqld[7389]: diagnose the problem, but since we have already crashed,
 
Feb 08 16:39:17 mon-db mysqld[7389]: something is definitely wrong and this may fail.
 
Feb 08 16:39:17 mon-db mysqld[7389]: Server version: 10.1.21-MariaDB-1~jessie
 
Feb 08 16:39:17 mon-db mysqld[7389]: key_buffer_size=8388608
 
Feb 08 16:39:17 mon-db mysqld[7389]: read_buffer_size=2097152
 
Feb 08 16:39:17 mon-db mysqld[7389]: max_used_connections=20
 
Feb 08 16:39:17 mon-db mysqld[7389]: max_threads=1002
 
Feb 08 16:39:17 mon-db mysqld[7389]: thread_count=7
 
Feb 08 16:39:17 mon-db mysqld[7389]: It is possible that mysqld could use up to
 
Feb 08 16:39:17 mon-db mysqld[7389]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6185039 K  bytes of memory
 
Feb 08 16:39:17 mon-db mysqld[7389]: Hope that's ok; if not, decrease some variables in the equation.
 
Feb 08 16:39:17 mon-db mysqld[7389]: Thread pointer: 0x7f5cb67ed008
 
Feb 08 16:39:17 mon-db mysqld[7389]: Attempting backtrace. You can use the following information to find out
 
Feb 08 16:39:17 mon-db mysqld[7389]: where mysqld died. If you see no messages after this, something went
 
Feb 08 16:39:17 mon-db mysqld[7389]: terribly wrong...
 
Feb 08 16:39:17 mon-db mysqld[7389]: stack_bottom = 0x7f5d339ad0b8 thread_stack 0x48400
 
Feb 08 16:39:17 mon-db mysqld[7389]: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x563f6c35aade]
 
Feb 08 16:39:17 mon-db mysqld[7389]: /usr/sbin/mysqld(handle_fatal_signal+0x2fd)[0x563f6be9612d]
 
Feb 08 16:39:17 mon-db mysqld[7389]: /lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f5d40430890]
 
Feb 08 16:39:17 mon-db mysqld[7389]: /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f5d3e6d3067]
 
Feb 08 16:39:17 mon-db mysqld[7389]: /lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f5d3e6d4448]
 
Feb 08 16:39:17 mon-db mysqld[7389]: /usr/sbin/mysqld(+0x715291)[0x563f6c005291]
 
Feb 08 16:39:17 mon-db mysqld[7389]: /usr/sbin/mysqld(+0x7192d0)[0x563f6c0092d0]
 
Feb 08 16:39:17 mon-db mysqld[7389]: /usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P14HA_CREATE_INFOP10TABLE_LISTP10Alter_infojP8st_orderb+0x2136)[0x563f6bd9cf76]
 
Feb 08 16:39:17 mon-db mysqld[7389]: /usr/sbin/mysqld(_Z20mysql_recreate_tableP3THDP10TABLE_LISTb+0x14f)[0x563f6bd9eb3f]

After i disable innodb_use_fallocate=ON , problem will disappear, but before DB working for several month with no problems.

 Comments   
Comment by Marko Mäkelä [ 2017-02-08 ]

"OS error 201" could actually mean errno 101, because os_file_get_last_error_low() is adding OS_FILE_ERROR_MAX (100) to unrecognized error codes.

Comment by Marko Mäkelä [ 2017-02-16 ]

I filed MDEV-12075 as a duplicate issue of this. I should really have read this one more carefully first.
This is a regression caused by MDEV-11556 and affects MariaDB Server 10.1.21 only.

Comment by Marko Mäkelä [ 2017-02-16 ]

Actually InnoDB could be adding the constant 100 twice to the error code 1 (EPERM, Operation not permitted), causing the misleading report "OS error 201"

Comment by Marko Mäkelä [ 2017-02-16 ]

For the record, the error code may vary depending on the file system:

2017-02-16  9:41:06 139742722718464 [ERROR] InnoDB: File ./mysql/innodb_table_stats.ibd: 'posix_fallocate' returned OS error 71.

71 is EPROTO (Protocol error). I guess that an attempt to posix_fallocate() 0 bytes at the end of a file could be called that.

Comment by Marko Mäkelä [ 2017-02-21 ]

The reported error code could be completely bogus.
The GNU/Linux manual page for posix_fallocate(3) says:

posix_fallocate() returns zero on success, or an error number on failure. Note that errno is not set.

The FreeBSD manual page says:

If successful, posix_fallocate() returns zero. It returns an error on failure, without setting errno.

But InnoDB is only checking for the return value -1, and assuming that any other return value means success. Furthermore, InnoDB is referring to errno in the error messages, revealing the status of some previously attempted operation, not posix_fallocate().
I plan to rectify the situation in MDEV-11520.

Generated at Thu Feb 08 07:54:33 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.