MySQL Bugs: #29155: Innodb "Parallel recovery" is not prevented

Bug #29155	Innodb "Parallel recovery" is not prevented
Submitted:	16 Jun 2007 13:53	Modified:	19 Jun 2010 17:45
Reporter:	Peter Zaitsev (Basic Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.0, 5.1	OS:	FreeBSD
Assigned to:	Vasil Dimov	CPU Architecture:	Any
Tags:	qc

Description:
Here is the log from FreeBSD host:

70616 14:32:49  mysqld restarted
070616 14:32:51  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...
070616 14:32:54  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 66 4211801414.
InnoDB: Doing recovery: scanned up to log sequence number 66 4217043968
InnoDB: Doing recovery: scanned up to log sequence number 66 4222286848
InnoDB: Doing recovery: scanned up to log sequence number 66 4227529728
InnoDB: Doing recovery: scanned up to log sequence number 66 4232772608
InnoDB: Doing recovery: scanned up to log sequence number 66 4238015488
InnoDB: Doing recovery: scanned up to log sequence number 66 4243258368
InnoDB: Doing recovery: scanned up to log sequence number 66 4248501248
InnoDB: Doing recovery: scanned up to log sequence number 66 4253744128
InnoDB: Doing recovery: scanned up to log sequence number 66 4258987008
InnoDB: Doing recovery: scanned up to log sequence number 66 4264229888
InnoDB: Doing recovery: scanned up to log sequence number 66 4269353916
070616 14:33:27  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 070616 14:34:33  mysqld started
65 66 67 68 070616 14:34: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...
69 70 070616 14:34:39  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 66 4211801414.
71 InnoDB: Doing recovery: scanned up to log sequence number 66 4217043968
72 InnoDB: Doing recovery: scanned up to log sequence number 66 4222286848
73 74 75 InnoDB: Doing recovery: scanned up to log sequence number 66 4227529728
76 InnoDB: Doing recovery: scanned up to log sequence number 66 4232772608
77 78 InnoDB: Doing recovery: scanned up to log sequence number 66 4238015488
79 80 InnoDB: Doing recovery: scanned up to log sequence number 66 4243258368
81 82 83 InnoDB: Doing recovery: scanned up to log sequence number 66 4248501248
84 85 InnoDB: Doing recovery: scanned up to log sequence number 66 4253744128
86 87 88 89 90 91 92 93 InnoDB: Doing recovery: scanned up to log sequence number 66 4258987008
94 InnoDB: Doing recovery: scanned up to log sequence number 66 4264229888

As you can see MySQL was automatically restarted because of crash and at the same time it was noticed MySQL is down and it was started  separaterly

At this point two innodb crash recovery processes run in parallel. 

In the end it causes the following problems after recovery:

070616 14:35:46  InnoDB: Error: page 3607 log sequence number 66 4269376081
InnoDB: is in the future! Current system log sequence number 66 4269353916.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: for more information.
070616 14:35:46  InnoDB: Error: page 3614 log sequence number 66 4269506762
InnoDB: is in the future! Current system log sequence number 66 4269353916.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See

How to repeat:
See above

Thank you for a problem report. While the problem is obvious from the logs, can you explain in more details how to repeat it? 

When I just tried to start another mysqld process I've got:

openxs@suse:~/dbs/5.0> InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.

Right I know this is especially why I mentioned this is FreeBSD system. 
Possibly it is platform specific bug or there is race condition. 

I have no way to play with MySQL as this is customers production system.

I have however seen this on multiple instances.

There was a related bug where '/etc/init.d/mysql restart' would leave two instances of MySQL running because it only waited for 30 seconds for mysqld to stop and then it would timeout and start a new mysqld process. I think that has been fixed by 5.0.41.

Mark, 

This is not exactly the same.  Even if mysqld_safe  tries to start second mysqld instance it should safely fail...  Either on Innodb trying to lock data file or on MySQL binding to the same port.  However this attempt by mysqld_safe may be nasty - I've seen socket file and pid file being removed in such case for example.

Hmm... looks like 'advisory file locking' does not work on FreeBSD.

Assigning this to Marko.

I am able to start 2 mysql instances on FreeBSD 7-CURRENT (from May 27) when I use --skip-networking option:

$ ./libexec/mysqld --skip-networking
070619  8:53:49  InnoDB: Started; log sequence number 0 46409
070619  8:53:50 [Note] Event Scheduler: Loaded 0 events
070619  8:53:50 [Note] ./libexec/mysqld: ready for connections.
Version: '5.1.20-beta-debug'  socket: '/tmp/mysql.sock'  port: 0  Source distribution

$ ./libexec/mysqld --skip-networking
070619  8:53:58  InnoDB: Started; log sequence number 0 46409
070619  8:53:59 [Note] Event Scheduler: Loaded 0 events
070619  8:53:59 [Note] ./libexec/mysqld: ready for connections.
Version: '5.1.20-beta-debug'  socket: '/tmp/mysql.sock'  port: 0  Source distribution

$ ps -ax |grep mysql
81972  p4  I+     0:00.43 ./libexec/mysqld --skip-networking
81992  pa  I+     0:00.43 ./libexec/mysqld --skip-networking

Vasil,

Thank you for confirming the bug. 

The good question is actually if this is Innodb problem when. I guess you can replace Innodb with any other storage engine here and results can always be pretty bad. 

May be MySQL should have its build in prevention of second start which is not storage engine dependent ?

Vasil,

does FreeBSD have any file locking mechanism that we could use here?

Regards,

Heikki

Peter,

> The good question is actually if this is Innodb problem when. I guess you can replace
> Innodb with any other storage engine here and results can always be pretty bad.
>
> May be MySQL should have its build in prevention of second start which is not storage
> engine dependent ?

Indeed. MySQL should protect its resources from another instances.
For example:
* The TCP port need no protection, "bind(): address already in use"
* The /tmp/mysql.sock file should be protected by /tmp/mysql.sock.lock dummy file (for example) being flock(2)'d
* The data directory should be protected in a similar way

Actually, if InnoDB is enabled, MySQL won't start a second instance because InnoDB cannot lock it's files, but this is disabled on FreeBSD:

os0file.c:
 457 #undef USE_FILE_LOCK
 458 #define USE_FILE_LOCK
 459 #if defined(UNIV_HOTBACKUP) || defined(__WIN__) || defined(__FreeBSD__) ||   defined(__NETWARE__)
 460 /* InnoDB Hot Backup does not lock the data files.
 461  * On Windows, mandatory locking is used.
 462  * On FreeBSD with LinuxThreads, advisory locking does not work properly.
 463  */
 464 # undef USE_FILE_LOCK
 465 #endif
 466 #ifdef USE_FILE_LOCK
 467 /********************************************************************
 468 Obtain an exclusive lock on a file. */
 469 static
 470 int
 471 os_file_lock(

So InnoDB behavior differs from Linux to FreeBSD, I am going to check what has been the problem with FreeBSD & LinuxThreads and if it has not been fixed already...

There is another question, 

The build I was using was not LinuxThreads FreeBSD it was normal FreeBSD build so may be this check needs to have further clarification and only apply to LinuxThreads on FreeBSD case ?

Yes, it is overdoing to always disable locking on FreeBSD.

I think that LinuxThreads can be distinguished because they define the symbol
__LT_SPINLOCK_INIT, so we can disable locking like this:
#if defined(__FreeBSD__) && defined(__LT_SPINLOCK_INIT)

Or even better:
#define is_linuxthreads defined(__LT_SPINLOCK_INIT)
#if defined(__FreeBSD__) && is_linuxthreads
... disable locking ...

Vasil intends to remove the whole FreeBSD special define. File locking seems to work on a modern FreeBSD, regardless of LinuxThreads.

Fix which enables locking on FreeBSD has been committed into the InnoDB 5.0 SVN tree under r1615 and into the 5.1 SVN tree under r1613.

Peter, here is the patch in case you want to test it before it goes into official MySQL releases (which may take months):

Index: os/os0file.c
===================================================================
--- os/os0file.c        (revision 1614)
+++ os/os0file.c        (revision 1615)
@@ -436,10 +436,9 @@
 
 #undef USE_FILE_LOCK
 #define USE_FILE_LOCK
-#if defined(UNIV_HOTBACKUP) || defined(__WIN__) || defined(__FreeBSD__) || defined(__NETWARE__)
+#if defined(UNIV_HOTBACKUP) || defined(__WIN__) || defined(__NETWARE__)
 /* InnoDB Hot Backup does not lock the data files.
  * On Windows, mandatory locking is used.
- * On FreeBSD with LinuxThreads, advisory locking does not work properly.
  */
 # undef USE_FILE_LOCK
 #endif

Also notice that there _is_ a MySQL problem that it starts twice over the same unix domain socket and data directory if InnoDB is disabled. You may want to open another bug report for that.

Thanks Vasil for prompt fix.

I trust you it works I will not be testing it myself but will let customer know.

Queued to 5.1-maint

Pushed into 5.1.21-beta

Queued to 5.0-maint

Pushed into 5.0.48

Pushed into 5.1.22-beta

Noted in 5.0.48, 5.1.21 changelogs.

InnoDB refused to start on some versions of FreeBSD with
LinuxThreads. This is fixed by enabling file locking on FreeBSD.

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)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.

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)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

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)