Bug #106280 innodb print tons of partial read in error log
Submitted: 25 Jan 2022 14:14 Modified: 28 Feb 2022 14:00
Reporter: WANG GUANGYOU Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7 OS:Any
Assigned to: CPU Architecture:Any

[25 Jan 2022 14:14] WANG GUANGYOU
Description:
I check the innodb code in  os_file_read_page. I find a bug that the function  may  looped forever and print tons of error log under some situation.

For example, if n_bytes != n and exit_on_error is ture
and the last errno is EAGAIN ,  it will loop for ever. For the pread in os_file_pread will not overwrite the errno status if it read less bytes even zero byte .

 

and will print line below repeatly

#############################
2022-01-20T11:44:27.405389+08:00 1988955 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
2022-01-20T11:44:27.405404+08:00 1988955 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
2022-01-20T11:44:27.405410+08:00 1988955 [Warning] InnoDB: 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
2022-01-20T11:44:27.405414+08:00 1988955 [Warning] InnoDB: Retry attempts for reading partial data failed.
2022-01-20T11:44:27.405421+08:00 1988955 [ERROR] InnoDB: Tried to read 16384 bytes at offset 49152, but was only able to read 0 of FD 2987, filename /opt/local/mysql/var/__recyclebin__/__innodb_5586.ibd
2022-01-20T11:44:27.405427+08:00 1988955 [ERROR] InnoDB: Operating system error number 11 in a file operation.
2022-01-20T11:44:27.405432+08:00 1988955 [ERROR] InnoDB: Error number 11 means 'Resource temporarily unavailable'
#############################

6187 /** Requests a synchronous positioned read operation.
 6188 @return DB_SUCCESS if request was successful, false if fail
 6189 @param[in]      type            IO flags
 6190 @param[in]      file            handle to an open file
 6191 @param[out]     buf             buffer where to read
 6192 @param[in]      offset          file offset from the start where to read
 6193 @param[in]      n               number of bytes to read, starting from offset
 6194 @param[out]     o               number of bytes actually read
 6195 @param[in]      exit_on_err     if true then exit on error
 6196 @return DB_SUCCESS or error code */
 6197 static MY_ATTRIBUTE((warn_unused_result))
 6198 dberr_t
 6199 os_file_read_page(
 6200         IORequest&      type,
 6201         os_file_t       file,
 6202         void*           buf,
 6203         os_offset_t     offset,
 6204         ulint           n,
 6205         ulint*          o,
 6206         bool            exit_on_err,
 6207         trx_t*          trx)
 6208 {
 6209         dberr_t         err;
 6210
 6211         os_bytes_read_since_printout += n;
 6212
 6213         ut_ad(type.validate());
 6214         ut_ad(n > 0);
 6215
              
 6216         for (;;) { 
 6217                 ssize_t n_bytes;
 6218 
                      
 6219                 n_bytes = os_file_pread(type, file, buf, n, offset, trx, &err);
 6220
 6221                 if (o != NULL) {
 6222                         *o = n_bytes;
 6223                 }
 6224
                      
 6225                 if (err != DB_SUCCESS && !exit_on_err) {
 6226
 6227                         return(err);
 6228
                     
 6229                 } else if ((ulint) n_bytes == n) {
 6230
 6231                         /*The page decryption failed - will handled by buf_io_comptelete*/
 6232                         if (err == DB_IO_DECRYPT_FAIL)
 6233                                 return (DB_IO_DECRYPT_FAIL);
 6234
 6235                         /** The read will succeed but decompress can fail
 6236                         for various reasons. */
 6237
 6238                         if (type.is_compression_enabled()
 6239                             && !Compression::is_compressed_page(
 6240                                     static_cast<byte*>(buf))) {
 6241
 6242                                 return(DB_SUCCESS);
 6243
 6244                         } else {
 6245                                 return(err);
 6246                         }
 6247                 }
 6248
                     
 6249                 const std::string fd_path = os_file_find_path_for_fd(file);
  6250                 if (!fd_path.empty()) {
 6251                         ib::error() << "Tried to read " << n
 6252                                     << " bytes at offset " << offset
 6253                                     << ", but was only able to read " << n_bytes
 6254                                     << " of FD " << file
 6255                                     << ", filename " << fd_path;
 6256                 } else {
 6257                         ib::error() << "Tried to read " << n
 6258                                     << " bytes at offset " << offset
 6259                                     << ", but was only able to read " << n_bytes;
 6260                 }
 6261
 6262                 if (exit_on_err) {
 6263
################################################################ 
if n_bytes != n and exit_on_error is ture
and the last errno is EAGAIN ,  it will loop for ever. For the pread in os_file_pread will not overwrite the errno status if it read less bytes even zero byte  
################################################################     
 6264                         if (!os_file_handle_error(NULL, "read")) {
 6265                                 /* Hard error */
 6266                                 break;
 6267                         }
 6268
 6269                 } else if (!os_file_handle_error_no_exit(NULL, "read", false)) {
 6270
 6271                         /* Hard error */
 6272                         break;
 6273                 }
 6274
 6275                 if (n_bytes > 0 && (ulint) n_bytes < n) {
 6276                         n -= (ulint) n_bytes;
 6277                         offset += (ulint) n_bytes;
 6278                         buf = reinterpret_cast<uchar*>(buf) + (ulint) n_bytes;
 6279                 }
 6280         }
 6281
 6282         ib::fatal()
 6283                 << "Cannot read from file. OS error number "
 6284                 << errno << ".";
 6285
 6286         return(err);
 6287 }

How to repeat:
check the code

Suggested fix:
I have two suggestion:
1,supress the error log. It prints two much
2,the errno is thread local. Before read, we should overwrite the errno to 0. Or it will spread all over the code . And it is not right to use the errno.
[25 Jan 2022 14:53] MySQL Verification Team
Hi Mr. GUANGYOU,

Thank you for your bug report.

However, we can not proceed in processing your report, without additional info.

First of all, we need a. fully reproducible test case. We need a test case that we would be able to repeat and got tons of messages in the error log.

Next, we got lots of requests for adding info to the error log and not the other way around.

Also, if you read our Manual, you can see that you can set verbosity of the error log.

But, most important of all, we need a fully repeatable test case. Otherwise, this report will not be further processed.
[27 Jan 2022 2:29] huahua xu
Hi Mr. GUANGYOU,

You be right! It may be a bug.

I find that the function my_pread overwrites the errno to 0 before it calls pread.
[26 Feb 2022 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".
[28 Feb 2022 14:00] MySQL Verification Team
Can't repeat without a test case and other infor.
[5 Sep 2022 10:36] peng gao
Hi Mr. GUANGYOU,

 I think this is a bug, I have the same problem , pread  && blocking regular file read 0 bytes not set errno,means EOF。
 
 {the number of bytes read is returned (zero indicates end of file)}
   
 so errno not overwrite ,if last errno is EAGAIN ,so loop for ever.
[19 Sep 2022 11:01] MySQL Verification Team
Hi,

We wrote before and we will repeat the same statement. That is , we can not process a bug report without a fully reproducible test case.
[10 May 2023 2:47] alex xing
I ran into a similar bug in MySQL5.7
mysql crash when update/insert

2023-05-10T07:51:15.447690+08:00 2397544 [Warning] InnoDB: Retry attempts for reading partial data failed.
2023-05-10T07:51:15.455348+08:00 2397544 [ERROR] InnoDB: Tried to read 16384 bytes at offset 890486784, but was only able to read 0
2023-05-10T07:51:15.455372+08:00 2397544 [ERROR] InnoDB: Operating system error number 61 in a file operation.
2023-05-10T07:51:15.455395+08:00 2397544 [ERROR] InnoDB: Error number 61 means 'No data available'
2023-05-10T07:51:15.455959+08:00 2397544 [Note] InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
2023-05-10T07:51:15.455971+08:00 2397544 [ERROR] InnoDB: File (unknown): 'read' returned OS error 161. Cannot continue operation
2023-05-10T07:51:15.455977+08:00 2397544 [ERROR] InnoDB: Cannot continue operation.
2023-05-10T07:51:19.861129+08:00 0 [Note] InnoDB: FTS optimize thread exiting.
2023-05-10T07:52:55.535093+08:00 2397544 [Warning] InnoDB: 3 threads created by InnoDB had not exited at shutdown!
2023-05-09T23:53:01.994835Z 0 [Warning] The syntax 'expire-logs-days' is deprecated and will be removed in a future release. Please use binlog_expire_logs_seconds instead.
[10 May 2023 12:01] MySQL Verification Team
Hi,

Version 5.7 now receives only fixes for the crashes and security problems.

So, this report would qualify if we could had a repeatable test case. We still have not got one !!!!!