Mysterious progress after recovery in MySQL Community Edition 5.1.34
Mysterious progress after recovery in MySQL Community Edition 5.1.34
am 12.06.2009 16:33:03 von Mike Spreitzer
--=_alternative 004FEB25852575D3_=
Content-Type: text/plain; charset="US-ASCII"
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
--=_alternative 004FEB25852575D3_=--
Re: Mysterious progress after recovery in MySQL Community Edition
am 12.06.2009 17:25:53 von Michael Dykman
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@gmail.com
- All models are wrong. Some models are useful.
--
MySQL General Mailing List
For list archives: http://lists.mysql.com/mysql
To unsubscribe: http://lists.mysql.com/mysql?unsub=3Dgcdmg-mysql-2@m.gmane.o rg
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
am 12.06.2009 17:50:40 von Mike Spreitzer
--=_alternative 005705DC852575D3_=
Content-Type: text/plain; charset="US-ASCII"
Yes, when the shutdown was initiated there was a huge "LOAD DATA" in
progress. Is there some server config change I should make that would
cause commits to happen occasionally during that operation? I know of no
way to resume such an operation after the server shutdown and eventual
restart, the best I could hope for would be to quickly delete the
partially loaded data and start loading it all over again, right? (Now I
see why it was suggested I break this data file up into smaller pieces.)
Thanks,
Mike Spreitzer
SMTP: mspreitz@us.ibm.com, Lotus Notes: Mike Spreitzer/Watson/IBM
Office phone: +1-914-784-6424 (IBM T/L 863-)
AOL Instant Messaging: M1k3Sprtzr
Michael Dykman
06/12/09 11:25 AM
To
Mike Spreitzer/Watson/IBM@IBMUS
cc
mysql@lists.mysql.com
Subject
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
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. 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
>
--
- michael dykman
- mdykman@gmail.com
- All models are wrong. Some models are useful.
--=_alternative 005705DC852575D3_=--
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
am 12.06.2009 18:57:34 von Mike Spreitzer
--=_alternative 005D2643852575D3_=
Content-Type: text/plain; charset="US-ASCII"
BTW, I have another instance of this problem right now. I will try
breaking that huge table up into chunks, but have not yet done so. I have
a "LOAD DATA LOCAL INFILE" in progress, and want to abort it (so I can try
the better way). I have ^Ced the `mysql` client twice, killing it. The
server continued working on that statement for a while. I then tried
`/usr/share/mysql/mysql.server stop`; that has been in progress for a
while now, has printed about 320 dots so far. What is the fastest way to
get this thing aborted?
Thanks,
Mike Spreitzer
SMTP: mspreitz@us.ibm.com, Lotus Notes: Mike Spreitzer/Watson/IBM
Office phone: +1-914-784-6424 (IBM T/L 863-)
AOL Instant Messaging: M1k3Sprtzr
Mike Spreitzer/Watson/IBM@IBMUS
06/12/09 11:50 AM
To
Michael Dykman
cc
mysql@lists.mysql.com
Subject
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
Yes, when the shutdown was initiated there was a huge "LOAD DATA" in
progress. Is there some server config change I should make that would
cause commits to happen occasionally during that operation? I know of no
way to resume such an operation after the server shutdown and eventual
restart, the best I could hope for would be to quickly delete the
partially loaded data and start loading it all over again, right? (Now I
see why it was suggested I break this data file up into smaller pieces.)
Thanks,
Mike Spreitzer
SMTP: mspreitz@us.ibm.com, Lotus Notes: Mike Spreitzer/Watson/IBM
Office phone: +1-914-784-6424 (IBM T/L 863-)
AOL Instant Messaging: M1k3Sprtzr
Michael Dykman
06/12/09 11:25 AM
To
Mike Spreitzer/Watson/IBM@IBMUS
cc
mysql@lists.mysql.com
Subject
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
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. 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
>
--
- michael dykman
- mdykman@gmail.com
- All models are wrong. Some models are useful.
--=_alternative 005D2643852575D3_=--
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
am 12.06.2009 20:18:10 von Mike Spreitzer
--=_alternative 00648696852575D3_=
Content-Type: text/plain; charset="US-ASCII"
I could afford to completely delete the schema (AKA database) into which
the "LOAD DATA LOCAL INFILE" is going. How exactly would I do that, given
that the server is still really busy shutting down? If necessary, in some
instances, I could afford to lose all the data on a given machine (and I
am not using replication) if necessary; is there a faster way to do that
than uninstall and reinstall?
Thanks,
Mike Spreitzer
Mike Spreitzer/Watson/IBM@IBMUS
06/12/09 12:57 PM
To
Michael Dykman
cc
mysql@lists.mysql.com
Subject
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
BTW, I have another instance of this problem right now. I will try
breaking that huge table up into chunks, but have not yet done so. I have
a "LOAD DATA LOCAL INFILE" in progress, and want to abort it (so I can try
the better way). I have ^Ced the `mysql` client twice, killing it. The
server continued working on that statement for a while. I then tried
`/usr/share/mysql/mysql.server stop`; that has been in progress for a
while now, has printed about 320 dots so far. What is the fastest way to
get this thing aborted?
Thanks,
Mike Spreitzer
Mike Spreitzer/Watson/IBM@IBMUS
06/12/09 11:50 AM
To
Michael Dykman
cc
mysql@lists.mysql.com
Subject
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
Yes, when the shutdown was initiated there was a huge "LOAD DATA" in
progress. Is there some server config change I should make that would
cause commits to happen occasionally during that operation? I know of no
way to resume such an operation after the server shutdown and eventual
restart, the best I could hope for would be to quickly delete the
partially loaded data and start loading it all over again, right? (Now I
see why it was suggested I break this data file up into smaller pieces.)
Thanks,
Mike Spreitzer
SMTP: mspreitz@us.ibm.com, Lotus Notes: Mike Spreitzer/Watson/IBM
Office phone: +1-914-784-6424 (IBM T/L 863-)
AOL Instant Messaging: M1k3Sprtzr
Michael Dykman
06/12/09 11:25 AM
To
Mike Spreitzer/Watson/IBM@IBMUS
cc
mysql@lists.mysql.com
Subject
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
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. 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
>
--
- michael dykman
- mdykman@gmail.com
- All models are wrong. Some models are useful.
--=_alternative 00648696852575D3_=--