List:General Discussion« Previous MessageNext Message »
From:Mike Spreitzer Date:June 12 2009 2:33pm
Subject:Mysterious progress after recovery in MySQL Community Edition 5.1.34
View as plain text  
A colleague had to kill a MySQL server (on RedHat Enterprise Linux 5) 
because it had some problem shutting down.  Later I launched it (with 
`/usr/share/mysql/mysql.server start`).  In its err log I saw the recovery 
happen, apparently with a successful completion, and then the usual 
announcement that the server is listening on its socket --- which I had 
taken to mean the server is ready to be used.  Apparently that's not quite 
right.  After that, I find another series of progress numbers is being 
written into the err log, one every few minutes (so the whole recovery 
will take hours!).  I see no obvious indication of what is progressing. 
Can anybody give me a clue about what is going on here?  Following is the 
tail of my err log right now, starting from some point in the last 
shutdown sequence:

Version: '5.1.34-community-log'  socket: '/var/lib/mysql/mysql.sock' port: 
3306  MySQL Community Server (GPL)
090611 22:59:59 [Note] /usr/sbin/mysqld: Normal shutdown

090611 22:59:59 [Note] Event Scheduler: Purging the queue. 0 events
090611 23:00:01 [Warning] /usr/sbin/mysqld: Forcing close of thread 2 
user: 'root'

090612 11:01:41 mysqld_safe Starting mysqld daemon with databases from 
/var/lib/mysql
090612 11:01:41 [Warning] The syntax '--log_slow_queries' is deprecated 
and will be removed in MySQL 7.0. Please use 
'--slow_query_log'/'--slow_query_log_file' instead.
InnoDB: Log scan progressed past the checkpoint lsn 4 1328926534
090612 11:01:41  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 4 1334169088
InnoDB: Doing recovery: scanned up to log sequence number 4 1339411968
InnoDB: Doing recovery: scanned up to log sequence number 4 1344654848
InnoDB: Doing recovery: scanned up to log sequence number 4 1349897728
InnoDB: Doing recovery: scanned up to log sequence number 4 1354899846
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 9403752 row operations to undo
InnoDB: Trx id counter is 0 18944
090612 11:01:47  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: Last MySQL binlog file position 0 235599817, file name 
./mysql-bin.000005
InnoDB: Starting in background the rollback of uncommitted transactions
090612 11:07:21  InnoDB: Rolling back trx with id 0 18568, 9403752 rows to 
undo

InnoDB: Progress in percents: 1090612 11:07:21  InnoDB: Started; log 
sequence number 4 1354899846
090612 11:07:21 [Note] Recovering after a crash using mysql-bin
090612 11:07:25 [Note] Starting crash recovery...
090612 11:07:25 [Note] Crash recovery finished.
090612 11:07:25 [Note] Event Scheduler: Loaded 0 events
090612 11:07:25 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.34-community-log'  socket: '/var/lib/mysql/mysql.sock' port: 
3306  MySQL Community Server (GPL)
 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



Thanks,
Mike Spreitzer

Thread
Mysterious progress after recovery in MySQL Community Edition 5.1.34Mike Spreitzer12 Jun
  • Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34Michael Dykman12 Jun
    • Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34Mike Spreitzer12 Jun
      • Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34Mike Spreitzer12 Jun
        • Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34Mike Spreitzer12 Jun