Bug #6263 InnoDB crashed when I updated my system time.

Description:
Hi,

I had InnoDB crash on me when I updated the system time with ntpdate on fedora core 2 using kernel 2.6.8-1.521smp.  I was importing thousands of records into several innodb tables when this crash happened.

Here's what I typed to update my system time:

[root@db01 root]# ntpdate time.windows.com
Looking for host time.windows.com and service ntp
host found : time.windows.com
26 Oct 08:31:06 ntpdate[20382]: step time server 207.46.130.100 offset 463.941654 sec

When I did this I noticed that InnoDB crashed, restarted and went into its automatic crash recovery (Thank god for this and I love you for it Mr. Tuuri!).  Here's everything that went into my .err error log.

041024  0:32:26  InnoDB: Started; log sequence number 19 1528826892
/usr/sbin/mysqld: ready for connections.
Version: '4.1.6-gamma-standard-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3307  Official MySQL RPM
041026  8:20:34  InnoDB: Operating system error number 22 in a file operation.
InnoDB: Error number 22 means 'Invalid argument'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/mysql/en/Operating_System_error_codes.html
InnoDB: File operation call: 'read'.
InnoDB: Cannot continue operation.

Number of processes running now: 0
041026 08:20:37  mysqld restarted
041026  8:20:37  [WARNING] Asked for 196608 thread stack, but got 126976
041026  8:20:38  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
041026  8:20:38  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 25 4099441171.
InnoDB: Doing recovery: scanned up to log sequence number 25 4104684032
InnoDB: Doing recovery: scanned up to log sequence number 25 4109926912
InnoDB: Doing recovery: scanned up to log sequence number 25 4115169792
InnoDB: Doing recovery: scanned up to log sequence number 25 4120412672
InnoDB: Doing recovery: scanned up to log sequence number 25 4125655552
InnoDB: Doing recovery: scanned up to log sequence number 25 4130898432
InnoDB: Doing recovery: scanned up to log sequence number 25 4136141312
InnoDB: Doing recovery: scanned up to log sequence number 25 4141384192
InnoDB: Doing recovery: scanned up to log sequence number 25 4146627072
InnoDB: Doing recovery: scanned up to log sequence number 25 4151869952
InnoDB: Doing recovery: scanned up to log sequence number 25 4157112832
InnoDB: Doing recovery: scanned up to log sequence number 25 4162355712
InnoDB: Doing recovery: scanned up to log sequence number 25 4167598592
InnoDB: Doing recovery: scanned up to log sequence number 25 4172841472
InnoDB: Doing recovery: scanned up to log sequence number 25 4178084352
InnoDB: Doing recovery: scanned up to log sequence number 25 4183327232
InnoDB: Doing recovery: scanned up to log sequence number 25 4188570112
InnoDB: Doing recovery: scanned up to log sequence number 25 4193812992
InnoDB: Doing recovery: scanned up to log sequence number 25 4199055872
InnoDB: Doing recovery: scanned up to log sequence number 25 4204298752
InnoDB: Doing recovery: scanned up to log sequence number 25 4209541632
InnoDB: Doing recovery: scanned up to log sequence number 25 4214784512
InnoDB: Doing recovery: scanned up to log sequence number 25 4220027392
InnoDB: Doing recovery: scanned up to log sequence number 25 4225270272
InnoDB: Doing recovery: scanned up to log sequence number 25 4230513152
InnoDB: Doing recovery: scanned up to log sequence number 25 4235756032
InnoDB: Doing recovery: scanned up to log sequence number 25 4240998912
InnoDB: Doing recovery: scanned up to log sequence number 25 4246241792
InnoDB: Doing recovery: scanned up to log sequence number 25 4251484672
InnoDB: Doing recovery: scanned up to log sequence number 25 4256727552
InnoDB: Doing recovery: scanned up to log sequence number 25 4261970432
InnoDB: Doing recovery: scanned up to log sequence number 25 4267213312
InnoDB: Doing recovery: scanned up to log sequence number 25 4272456192
InnoDB: Doing recovery: scanned up to log sequence number 25 4277699072
InnoDB: Doing recovery: scanned up to log sequence number 25 4282941952
InnoDB: Doing recovery: scanned up to log sequence number 25 4288184832
InnoDB: Doing recovery: scanned up to log sequence number 25 4293427712
InnoDB: Doing recovery: scanned up to log sequence number 26 3703296
InnoDB: Doing recovery: scanned up to log sequence number 26 8946176
InnoDB: Doing recovery: scanned up to log sequence number 26 14189056
InnoDB: Doing recovery: scanned up to log sequence number 26 19431936
InnoDB: Doing recovery: scanned up to log sequence number 26 24674816
InnoDB: Doing recovery: scanned up to log sequence number 26 29917696
InnoDB: Doing recovery: scanned up to log sequence number 26 35160576
InnoDB: Doing recovery: scanned up to log sequence number 26 40403456
InnoDB: Doing recovery: scanned up to log sequence number 26 45646336
InnoDB: Doing recovery: scanned up to log sequence number 26 50889216
InnoDB: Doing recovery: scanned up to log sequence number 26 56132096
InnoDB: Doing recovery: scanned up to log sequence number 26 61374976
InnoDB: Doing recovery: scanned up to log sequence number 26 66617856
InnoDB: Doing recovery: scanned up to log sequence number 26 71860736
InnoDB: Doing recovery: scanned up to log sequence number 26 77103616
InnoDB: Doing recovery: scanned up to log sequence number 26 82346496
InnoDB: Doing recovery: scanned up to log sequence number 26 87589376
InnoDB: Doing recovery: scanned up to log sequence number 26 92832256
InnoDB: Doing recovery: scanned up to log sequence number 26 98075136
InnoDB: Doing recovery: scanned up to log sequence number 26 103318016
InnoDB: Doing recovery: scanned up to log sequence number 26 104347602
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 888 row operations to undo
InnoDB: Trx id counter is 0 1997312
041026  8:21:20  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Starting rollback of uncommitted transactions
InnoDB: Rolling back trx with id 0 1997031, 888 rows to undo
InnoDB: Rolling back of trx id 0 1997031 completed
InnoDB: Rollback of uncommitted transactions completed
041026  8:37:56  InnoDB: Flushing modified pages from the buffer pool...
041026  8:38:20  InnoDB: Started; log sequence number 26 104347602
/usr/sbin/mysqld: ready for connections.
Version: '4.1.6-gamma-standard-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3307  Official MySQL RPM

How to repeat:
It's in the description.

Suggested fix:
I don't know. :)

see bug #5898, will be fixed in 4.0.22 and 4.1.7

Hartmut,
I was about to suggest the same, but according to "bk changes", 4.1.6 was tagged later than the fix to bug #5898 was merged from 4.0 to 4.1. Are you sure that bug #5898 was not fixed in 4.1.6? Furthermore, the posted log does not include any error message about an excessive lock wait timeout.
In order to better investigate this, we'd need a repeatable test case. Gil, can you try again if you can get mysqld to crash under similar circumstances?

I upgraded to 4.1.7 and have been unable to reproduce the crash.  I will downgrade on a devel server and test again sometime tonight.

Hi!

This is not any semaphore wait timeout problem, but a file i/o problem. Maybe Linux has some bug that if you move the system clock, a file read can fail with error 22?

Regards,

Heikki

Hi!

I am changing the status of this bug report to "Won't fix", because this most probably is a Linux bug. You should report this bug to the maintainers of Fedora Core(dump).

Regards,

Heikki