[Maia-users] web pages hang on maia, forced to reboot server. ..
Kurt Buff
KBuff at zetron.com
Mon Jul 30 17:42:25 PDT 2007
First - Thanks for your continuing help on this, Robert and David, and
David. :)
Notes below...
Robert LeBlanc wrote:
> Sent: Wednesday, July 25, 2007 15:52
> To: 'maia-users at renaissoft.com'
> Subject: Re: [Maia-users] web pages hang on maia, forced to reboot
> server. ..
>
>
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> Kurt Buff wrote:
>
> > Update below - the problem isn't resolved.
>
> - From what you're describing, it sounds like your problem
> may be with a
> corrupt MySQL table or index. Have you checked your MySQL logs for
> indications of any errors?
>
> What happens (disturbingly often, it seems, with MySQL) is that the
> bayes_token table gets corrupted--it's the busiest table in the
> database, so it's the most likely to get corrupted--and when that
> happens MySQL shuts down and tries to restart itself, over and over
> again. What you get is intermittent database connectivity: the
> connection attempts that hit the server during the seconds or minutes
> that it's alive and running go through, but the ones that arrive while
> mysqld is restarting can't connect.
>
> The fact that you're seeing database connection failures from
> amavisd-maia, the process-quarantine script, and the PHP scripts all
> point to intermittent database failures. I'd investigate your MySQL
> logs, as that seems to be the heart of the problem.
>
> If it does turn out to be a table/index corruption, you can use
> mysqldump to salvage what information you can from the affected table
> and then drop and recreate the table and reload that data.
> If it's any
> of the bayes_* tables, though, just drop and recreate all of
> them--they'll regenerate on their own over the course of a day or two.
> This was discussed a few weeks ago on this list, so there's
> more advice
> on this in the archives if you need it.
>
> As for why tables get corrupted in the first place, that's a matter of
> debate. Some people blame bugs in MySQL, while the MySQL devs claim
> InnoDB tables aren't corruptible unless your hardware (disk or RAM) is
> faulty. Personally, I've seen it happen with bad RAM, which
> causes the
> data to be corrupted in the write cache before it's handed to the
> filesystem. Clearly it could also be caused by a faulty drive, but
> that's usually much easier to diagnose.
OK - I've looked at the log (/var/db/mysql/zmx1.zetron.com.err), and find
the follwing from the most recent two reboots. I'm not seeing anything that
tells me what happened, but that may be due to my inexperience. Prior to the
24th, the last message in the error log is from the 18th. Are the logs below
indicating any particular kind of corruption? Is the error logging in MySQL
set high enough to tell, and if not, how do I set it higher?
Before I put down the logs, a further note: I have lots of files that I
don't understand in /var/db/mysql, and wonder if they can/should be deleted
or left alone - in particular:
-rw-rw---- 1 mysql mysql 10485760 Mar 28 15:46 log.0000000001
-rw-rw---- 1 mysql mysql 20856 Mar 24 16:25 mysql-bin.000001
-rw-rw---- 1 mysql mysql 500345 Mar 24 16:25 mysql-bin.000002
-rw-rw---- 1 mysql mysql 51086 Mar 28 15:46 mysql-bin.000003
-rw-rw---- 1 mysql mysql 121 Mar 29 15:35 mysql-bin.000004
-rw-rw---- 1 mysql mysql 698411 Mar 31 18:02 mysql-bin.000005
-rw-rw---- 1 mysql mysql 5989 Apr 2 11:33 mysql-bin.000006
-rw-rw---- 1 mysql mysql 50411 Apr 3 11:36 mysql-bin.000007
-rw-rw---- 1 mysql mysql 80734 Apr 3 16:23 mysql-bin.000008
-rw-rw---- 1 mysql mysql 278631 Apr 4 11:08 mysql-bin.000009
-rw-rw---- 1 mysql mysql 121 Apr 4 12:29 mysql-bin.000010
-rw-rw---- 1 mysql mysql 121 Apr 4 12:37 mysql-bin.000011
-rw-rw---- 1 mysql mysql 121 Apr 4 13:05 mysql-bin.000012
-rw-rw---- 1 mysql mysql 4285 Apr 4 16:09 mysql-bin.000013
-rw-rw---- 1 mysql mysql 2510 Apr 5 11:42 mysql-bin.000014
-rw-rw---- 1 mysql mysql 121 Apr 5 12:54 mysql-bin.000015
-rw-rw---- 1 mysql mysql 304404 Apr 9 11:40 mysql-bin.000016
-rw-rw---- 1 mysql mysql 307604 Apr 11 12:24 mysql-bin.000017
-rw-rw---- 1 mysql mysql 121 Apr 11 16:02 mysql-bin.000018
-rw-rw---- 1 mysql mysql 1706289 Apr 16 17:11 mysql-bin.000019
-rw-rw---- 1 mysql mysql 59714 Apr 18 17:09 mysql-bin.000020
-rw-rw---- 1 mysql mysql 1518559 May 15 15:21 mysql-bin.000021
-rw-rw---- 1 mysql mysql 7738329 Jun 18 18:28 mysql-bin.000022
-rw-rw---- 1 mysql mysql 501809 Jun 20 11:33 mysql-bin.000023
-rw-rw---- 1 mysql mysql 13282798 Jun 21 14:29 mysql-bin.000024
-rw-rw---- 1 mysql mysql 1073823319 Jun 25 07:12 mysql-bin.000025
-rw-rw---- 1 mysql mysql 1073855021 Jun 26 07:30 mysql-bin.000026
-rw-rw---- 1 mysql mysql 389889298 Jun 26 12:10 mysql-bin.000027
-rw-rw---- 1 mysql mysql 1073743718 Jun 27 13:37 mysql-bin.000028
-rw-rw---- 1 mysql mysql 1020217184 Jun 28 11:37 mysql-bin.000029
-rw-rw---- 1 mysql mysql 1073772420 Jun 29 13:01 mysql-bin.000030
-rw-rw---- 1 mysql mysql 1073746259 Jul 1 11:22 mysql-bin.000031
-rw-rw---- 1 mysql mysql 1073871409 Jul 2 12:01 mysql-bin.000032
-rw-rw---- 1 mysql mysql 1073810883 Jul 3 11:02 mysql-bin.000033
-rw-rw---- 1 mysql mysql 1073742098 Jul 5 03:00 mysql-bin.000034
-rw-rw---- 1 mysql mysql 1073769051 Jul 6 04:29 mysql-bin.000035
-rw-rw---- 1 mysql mysql 1073787772 Jul 7 16:47 mysql-bin.000036
-rw-rw---- 1 mysql mysql 1074214132 Jul 9 09:08 mysql-bin.000037
-rw-rw---- 1 mysql mysql 1074486763 Jul 10 06:23 mysql-bin.000038
-rw-rw---- 1 mysql mysql 1073855584 Jul 11 08:02 mysql-bin.000039
-rw-rw---- 1 mysql mysql 1073751939 Jul 12 10:03 mysql-bin.000040
-rw-rw---- 1 mysql mysql 1073891206 Jul 13 15:07 mysql-bin.000041
-rw-rw---- 1 mysql mysql 1073820581 Jul 16 01:32 mysql-bin.000042
-rw-rw---- 1 mysql mysql 1073746401 Jul 16 15:04 mysql-bin.000043
-rw-rw---- 1 mysql mysql 1073857032 Jul 17 11:01 mysql-bin.000044
-rw-rw---- 1 mysql mysql 1073751302 Jul 18 10:05 mysql-bin.000045
-rw-rw---- 1 mysql mysql 1073747642 Jul 19 08:08 mysql-bin.000046
-rw-rw---- 1 mysql mysql 1073880494 Jul 20 13:07 mysql-bin.000047
-rw-rw---- 1 mysql mysql 1073776926 Jul 22 18:12 mysql-bin.000048
-rw-rw---- 1 mysql mysql 1073741979 Jul 23 12:37 mysql-bin.000049
-rw-rw---- 1 mysql mysql 1074394453 Jul 24 14:54 mysql-bin.000050
-rw-rw---- 1 mysql mysql 1073794481 Jul 25 15:14 mysql-bin.000051
-rw-rw---- 1 mysql mysql 1079202640 Jul 26 16:28 mysql-bin.000052
-rw-rw---- 1 mysql mysql 1075369665 Jul 27 10:28 mysql-bin.000053
-rw-rw---- 1 mysql mysql 1073811703 Jul 29 17:01 mysql-bin.000054
-rw-rw---- 1 mysql mysql 1073850267 Jul 30 16:05 mysql-bin.000055
-rw-rw---- 1 mysql mysql 114326122 Jul 30 17:35 mysql-bin.000056
070724 18:11:36 [Note] /usr/local/libexec/mysqld: Normal shutdown
070724 18:11:36 [Note] SCHEDULER: Purging queue. 0 events
070724 18:11:38 [Warning] /usr/local/libexec/mysqld: Forcing close of thread
190276 user: 'vscan'
<snip 23 more of the above, concerning different thread numbers>
070724 18:14:31 mysqld started
070724 18:14:33 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...
070724 18:14:35 InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 4 2418860309.
InnoDB: Doing recovery: scanned up to log sequence number 4 2418860309
InnoDB: 8 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 202 row operations to undo
InnoDB: Trx id counter is 0 30794240
InnoDB: Last MySQL binlog file position 0 1074394453, file name
./mysql-bin.000050
InnoDB: Starting in background the rollback of uncommitted transactions
070724 18:14:35 InnoDB: Rolling back trx with id 0 30793771, 1 rows to undo
070724 18:14:35 InnoDB: Started; log sequence number 4 2418860309
InnoDB: Rolling back of trx id 0 30793771 completed
070724 18:14:35 InnoDB: Rolling back trx with id 0 30793757, 1 rows to undo
InnoDB: Rolling back of trx id 0 30793757 completed
070724 18:14:35 InnoDB: Rolling back trx with id 0 30793743, 1 rows to undo
InnoDB: Rolling back of trx id 0 30793743 completed
070724 18:14:35 InnoDB: Rolling back trx with id 0 30793719, 45 rows to
undo
070724 18:14:35 [Note] Recovering after a crash using mysql-bin
InnoDB: Rolling back of trx id 0 30793719 completed
070724 18:14:36 InnoDB: Rolling back trx with id 0 30793694, 1 rows to undo
InnoDB: Rolling back of trx id 0 30793694 completed
070724 18:14:36 InnoDB: Rolling back trx with id 0 30793670, 1 rows to undo
InnoDB: Rolling back of trx id 0 30793670 completed
070724 18:14:36 InnoDB: Rolling back trx with id 0 30793658, 1 rows to undo
InnoDB: Rolling back of trx id 0 30793658 completed
070724 18:14:36 InnoDB: Rolling back trx with id 0 30793655, 151 rows to
undo
InnoDB: Rolling back of trx id 0 30793655 completed
070724 18:14:41 InnoDB: Rollback of non-prepared transactions completed
070724 18:15:21 [Note] Starting crash recovery...
070724 18:15:21 [Note] Crash recovery finished.
070724 18:15:21 [Note] /usr/local/libexec/mysqld: ready for connections.
Version: '5.1.16-beta-log' socket: '/tmp/mysql.sock' port: 3306 FreeBSD
port: mysql-server-5.1.16
070724 18:15:21 [Note] SCHEDULER: Loaded 0 events
070727 6:43:16 [Note] /usr/local/libexec/mysqld: Normal shutdown
070727 6:43:16 [Note] SCHEDULER: Purging queue. 0 events
070727 6:43:18 [Warning] /usr/local/libexec/mysqld: Forcing close of thread
69273 user: 'vscan'
<snip 70 lines more of the above, concerning different thread numbers>
070727 06:46:02 mysqld started
070727 6:46:04 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...
070727 6:46:06 InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 4 3867116817.
InnoDB: Doing recovery: scanned up to log sequence number 4 3867116817
InnoDB: 8 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 88 row operations to undo
InnoDB: Trx id counter is 0 33000448
InnoDB: Last MySQL binlog file position 0 1079202640, file name
./mysql-bin.000052
InnoDB: Starting in background the rollback of uncommitted transactions
070727 6:46:06 InnoDB: Rolling back trx with id 0 33000067, 1 rows to undo
070727 6:46:06 InnoDB: Started; log sequence number 4 3867116817
InnoDB: Rolling back of trx id 0 33000067 completed
070727 6:46:06 InnoDB: Rolling back trx with id 0 33000044, 1 rows to undo
InnoDB: Rolling back of trx id 0 33000044 completed
070727 6:46:06 InnoDB: Rolling back trx with id 0 33000042, 1 rows to undo
070727 6:46:06 [Note] Recovering after a crash using mysql-bin
InnoDB: Rolling back of trx id 0 33000042 completed
070727 6:46:06 InnoDB: Rolling back trx with id 0 33000033, 32 rows to
undo
InnoDB: Rolling back of trx id 0 33000033 completed
070727 6:46:07 InnoDB: Rolling back trx with id 0 33000023, 1 rows to undo
InnoDB: Rolling back of trx id 0 33000023 completed
070727 6:46:07 InnoDB: Rolling back trx with id 0 33000009, 1 rows to undo
InnoDB: Rolling back of trx id 0 33000009 completed
070727 6:46:07 InnoDB: Rolling back trx with id 0 32999982, 1 rows to undo
InnoDB: Rolling back of trx id 0 32999982 completed
070727 6:46:07 InnoDB: Rolling back trx with id 0 32999968, 50 rows to
undo
InnoDB: Rolling back of trx id 0 32999968 completed
070727 6:46:09 InnoDB: Rollback of non-prepared transactions completed
070727 6:46:36 [Note] Starting crash recovery...
070727 6:46:36 [Note] Crash recovery finished.
070727 6:46:36 [Note] /usr/local/libexec/mysqld: ready for connections.
Version: '5.1.16-beta-log' socket: '/tmp/mysql.sock' port: 3306 FreeBSD
port: mysql-server-5.1.16
070727 6:46:36 [Note] SCHEDULER: Loaded 0 events
More information about the Maia-users
mailing list