Mysterious progress after recovery in MySQL Community Edition 5.1.34
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.05 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
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 Spreitzermspre...@us.ibm.com 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.05 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 - mdyk...@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=arch...@jab.org
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: mspre...@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 mdyk...@gmail.com 06/12/09 11:25 AM To Mike Spreitzer/Watson/i...@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 Spreitzermspre...@us.ibm.com 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.05 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 - mdyk...@gmail.com - All models are wrong. Some models are useful.
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 SMTP: mspre...@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/i...@ibmus 06/12/09 11:50 AM To Michael Dykman mdyk...@gmail.com 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: mspre...@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 mdyk...@gmail.com 06/12/09 11:25 AM To Mike Spreitzer/Watson/i...@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 Spreitzermspre...@us.ibm.com 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.05 InnoDB: Starting in background
Re: Mysterious progress after recovery in MySQL Community Edition 5.1.34
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/i...@ibmus 06/12/09 12:57 PM To Michael Dykman mdyk...@gmail.com 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/i...@ibmus 06/12/09 11:50 AM To Michael Dykman mdyk...@gmail.com 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: mspre...@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 mdyk...@gmail.com 06/12/09 11:25 AM To Mike Spreitzer/Watson/i...@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 Spreitzermspre...@us.ibm.com 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
