Description:
At the moment when falcon is doing recovery or allocating its buffers at the
start of the database, it does nothing to hint what it is doing and how
much progress has been made. This not user-friendly, as the user is left to
wonder if something useful is going on or the server is just looping/sleeping
in wait of some resource (I personally thought it was hung until I've
checked iostat and used gdb to find out that it is falcon doing something
that looks like recovery)
In contrast, when InnoDB does recovery we get something like this in the
server's stderr:
InnoDB: Log scan progressed past the checkpoint lsn 0 352045727
090427 21:27:28 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...
InnoDB: Doing recovery: scanned up to log sequence number 0 353378594
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 20000 row operations to undo
InnoDB: Trx id counter is 0 4352
090427 21:27:30 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 in background the rollback of uncommitted transactions
090427 21:27:31 InnoDB: Rolling back trx with id 0 3842, 20000 rows to undo
InnoDB: Progress in percents: 1090427 21:27:31 InnoDB: Started; log sequence number 0 353378594
2 3 4 5 6 7 8 9 10 11 12 13
090427 21:27:31 [Note] ./mysqld: ready for connections.
Version: '6.0.11-alpha-debug' socket: '/tmp/mysql.sock' port: 3306 Source distribution
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 100
InnoDB: Rolling back of trx id 0 3842 completed
090427 21:27:32 InnoDB: Rollback of non-prepared transactions completed
How to repeat:
[preferably on a slow machine]
Start server, load a bunch of data into Falcon without committing, kill falcon.
Re-start the server
Suggested fix:
Make falcon print progress when doing potentially lengthy operations on startup and shutdown (yes shutdown is also important so people don't kill the server assuming it hung on shutdown).
