From: Michael Dykman Date: June 12 2009 3:25pm Subject: Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34 List-Archive: http://lists.mysql.com/mysql/217850 Message-Id: <814b9a820906120825w422cdee7rf1449c6fa4fae312@mail.gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable It looks to me like you had trouble shutting down because you were in the middle of a HUGE transaction.. having been killed, a rollback of nearly 10 million statement need be run. I would suggest that somewhere in your processing, you are holding one connection open a long time, doing a lot of work, but failing to commit it periodically. On Fri, Jun 12, 2009 at 10:33 AM, Mike Spreitzer wrote= : > A colleague had to kill a MySQL server (on RedHat Enterprise Linux 5) > because it had some problem shutting down. =A0Later I launched it (with > `/usr/share/mysql/mysql.server start`). =A0In its err log I saw the recov= ery > 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. =A0Apparently that's not qu= ite > right. =A0After 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!). =A0I see no obvious indication of what is progressing. > Can anybody give me a clue about what is going on here? =A0Following is t= he > tail of my err log right now, starting from some point in the last > shutdown sequence: > > Version: '5.1.34-community-log' =A0socket: '/var/lib/mysql/mysql.sock' po= rt: > 3306 =A0MySQL 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 =A0InnoDB: 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 =A0InnoDB: 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 4= 2 > 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 6= 7 > 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 9= 2 > 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 =A0InnoDB: Rolling back trx with id 0 18568, 9403752 rows= to > undo > > InnoDB: Progress in percents: 1090612 11:07:21 =A0InnoDB: 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' =A0socket: '/var/lib/mysql/mysql.sock' po= rt: > 3306 =A0MySQL Community Server (GPL) > =A02 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 > --=20 - michael dykman - mdykman@stripped - All models are wrong. Some models are useful.