restarts in mysql_error log

[jbaskew]

Currently running zcs 7.2.0 ga ubuntu 10 64-bit and for some reason I'm having to start mysql.server as it just quits every so often. It was originally 7.1.4 and we never had any issue. It ran for months and I never had to restart or start stopped services. We upgraded to 7.2.0 last week (this is really just for testing right now, we have only 2 users on this box) and everyday I have to start mysql.server. If I'm understanding mysql_error.log, it would appear that mysql is restarting every few minutes as I see "socket '/opt/zimbra/db/mysql.sock' port: 7306 Source distribution killed" and mysqld_safe restarted, starting crash recovery, etc over and over every few minutes.

Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
Killed
120524 15:00:04 mysqld_safe Number of processes running now: 0
120524 15:00:04 mysqld_safe mysqld restarted
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
120524 15:00:05  InnoDB: Initializing buffer pool, size = 110.0M
120524 15:00:05  InnoDB: Completed initialization of buffer pool
120524 15:00:05  InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 89102219
120524 15:00:05  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 89103760
120524 15:00:14  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
120524 15:00:14 InnoDB Plugin 1.0.17 started; log sequence number 89103760
120524 15:00:14 [Note] Event Scheduler: Loaded 0 events
120524 15:00:14 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
Killed
120524 15:00:20 mysqld_safe Number of processes running now: 0
120524 15:00:20 mysqld_safe mysqld restarted
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
120524 15:00:20  InnoDB: Initializing buffer pool, size = 110.0M
120524 15:00:20  InnoDB: Completed initialization of buffer pool
120524 15:00:20  InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
120524 15:00:20  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...
120524 15:00:21 InnoDB Plugin 1.0.17 started; log sequence number 89103848
120524 15:00:21 [Note] Event Scheduler: Loaded 0 events
120524 15:00:21 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
Killed
120524 15:02:54 mysqld_safe Number of processes running now: 0
120524 15:02:54 mysqld_safe mysqld restarted
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
120524 15:02:56  InnoDB: Initializing buffer pool, size = 110.0M
120524 15:02:56  InnoDB: Completed initialization of buffer pool
120524 15:02:56  InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 89118224
120524 15:02:56  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 89120213
120524 15:03:01  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 3
5 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 7
5 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
120524 15:03:01 InnoDB Plugin 1.0.17 started; log sequence number 89120213
120524 15:03:01 [Note] Event Scheduler: Loaded 0 events
120524 15:03:01 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
Killed

I took that snippit before the last time I was aware that mysql had shutdown. We would like to start migrating users soon.

Thanks in advance

[jbaskew]

Tacky op reply. Well I see something in the error log that I either missed or didn't see before. A couple error lines. I'll go ahead and address the memory issue and keep an eye on it.

Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
Killed
120222 17:50:09 mysqld_safe Number of processes running now: 0
120222 17:50:09 mysqld_safe mysqld restarted
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
120222 17:50:10  InnoDB: Initializing buffer pool, size = 110.0M
InnoDB: mmap(117948416 bytes) failed; errno 12
120222 17:50:10InnoDB: Fatal error: cannot allocate the memory for the buffer pool
120222 17:50:10 [ERROR] Plugin 'InnoDB' init function returned error.
120222 17:50:10 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
120222 17:50:10 [Note] Event Scheduler: Loaded 0 events
120222 17:50:10 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
120223  9:05:13 [Note] /opt/zimbra/mysql/libexec/mysqld: Normal shutdown

120223  9:05:13 [Note] Event Scheduler: Purging the queue. 0 events
120223  9:05:13 [Note] /opt/zimbra/mysql/libexec/mysqld: Shutdown complete

120223 09:05:13 mysqld_safe mysqld from pid file /opt/zimbra/db/mysql.pid ended
120223 09:06:19 mysqld_safe Starting mysqld daemon with databases from /opt/zimbra/db/data
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
120223  9:06:19  InnoDB: Initializing buffer pool, size = 110.0M
120223  9:06:19  InnoDB: Completed initialization of buffer pool
120223  9:06:19  InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
120223  9:06:19  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...
120223  9:06:20 InnoDB Plugin 1.0.17 started; log sequence number 235235
120223  9:06:20 [Note] Event Scheduler: Loaded 0 events
120223  9:06:20 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
Killed
120223 23:30:22 mysqld_safe Number of processes running now: 0
120223 23:30:22 mysqld_safe mysqld restarted
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
120223 23:30:23  InnoDB: Initializing buffer pool, size = 110.0M
120223 23:30:23  InnoDB: Completed initialization of buffer pool
120223 23:30:23  InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
120223 23:30:23  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...
120223 23:30:23 InnoDB Plugin 1.0.17 started; log sequence number 986701
120223 23:30:23 [Note] Event Scheduler: Loaded 0 events
120223 23:30:23 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
Killed
120224 13:12:11 mysqld_safe Number of processes running now: 0
120224 13:12:11 mysqld_safe mysqld restarted
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
120224 13:12:11  InnoDB: Initializing buffer pool, size = 110.0M
120224 13:12:11  InnoDB: Completed initialization of buffer pool
120224 13:12:11  InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
120224 13:12:11  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...
120224 13:12:12 InnoDB Plugin 1.0.17 started; log sequence number 1293401
120224 13:12:12 [Note] Event Scheduler: Loaded 0 events
120224 13:12:12 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.58-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
Killed
120224 15:09:16 mysqld_safe Number of processes running now: 0
120224 15:09:16 mysqld_safe mysqld restarted
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
120224 15:09:17  InnoDB: Initializing buffer pool, size = 110.0M
120224 15:09:17  InnoDB: Completed initialization of buffer pool
120224 15:09:17  InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
120224 15:09:17  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...
120224 15:09:21 InnoDB Plugin 1.0.17 started; log sequence number 1322052
120224 15:09:21 [Note] Event Scheduler: Loaded 0 events
120224 15:09:21 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.

[phoenix]

Tacky op reply. Well I see something in the error log that I either missed or didn't see before. A couple error lines. I'll go ahead and address the memory issue and keep an eye on it.

How much RAM is on this server and how many users?

[jbaskew]

How much RAM is on this server and how many users?

Right now, 2GiB ram and only about 100 total and 5 active users .

--
Brad

[phoenix]

Right now, 2GiB ram and only about 100 total and 5 active users

The recommended minimum for a production server is 4GB of RAM although the current 2GB should be adequate for testing. Is this a VM or bare metal installation?

[jbaskew]

How much RAM is on this server and how many users?

My bad! This is a vm which only had 786mB from the creation of the vm. I was thinking this was a physical machine with more memory. So only 786. If I though emoticons weren't kind of lame. I'd use one with the awkward smile.

[phoenix]

My bad! This is a vm which only had 786mB from the creation of the vm. I was thinking this was a physical machine with more memory. So only 786

The lack of RAM would be the likely cause of the problem.

. If I though emoticons weren't kind of lame. I'd use one with the awkward smile.

You're disparaging a great piece of internet history there. Although I use them occasionally I tend to agree with your sentiment.

[jbaskew]

The recommended minimum for a production server is 4GB of RAM although the current 2GB should be adequate for testing. Is this a VM or bare metal installation?

The bare metal box we I had first been given to use had well more that 4GiB. But it was quicker to get a vm running so vm admin dolled me out a machine and it's sitting only at 786. I hadn't worried about the min requirement as the bare metal machine had well over the min req. Sorry to waste your time. I'm sure that's all that's going on. <facepalm>

[phoenix]

The bare metal box we I had first been given to use had well more that 4GiB. But it was quicker to get a vm running so vm admin dolled me out a machine and it's sitting only at 786. I hadn't worried about the min requirement as the bare metal machine had well over the min req. Sorry to waste your time.

That's OK, it's not a waste of time. If there's any problems when you increase the memory then post again.