ZCS 7.0 MySQL - Unknown table engine

[Jesster]

Hi Everyone,

I'm running 7.0 FOSS on Centos 5.5 64bit (4GB RAM) and have run into an odd issue after an upgrade from 6.0.10. This is a very small installation, but with very large mailboxes (~50GB).

This is a single-server installation.

While running imapsync to migrate another mailbox to my ZCS 7 server, I started getting errors about unable to create IMAP folders.

Here's a log snippet when I send an email to the mailbox (from mailbox.log):



2011-02-11 09:15:23,642 INFO [LmtpServer-13796] [name=work@example.net;mid=5;ip=1.2.3.4;] lmtp - try again for message work@example.net: exception occurred
com.zimbra.common.service.ServiceException: system failure: fetching folder data for mailbox 5
ExceptionId:LmtpServer-13796:1297444523642:b80e3d2bc8d5f7fa
Code:service.FAILURE
at com.zimbra.common.service.ServiceException.FAILURE (ServiceException.java:248)
at com.zimbra.cs.db.DbMailItem.getFoldersAndTags(DbMa ilItem.java:2095)
at com.zimbra.cs.mailbox.Mailbox.loadFoldersAndTags(M ailbox.java:1525)
at com.zimbra.cs.mailbox.Mailbox.beginTransaction(Mai lbox.java:1230)
at com.zimbra.cs.mailbox.Mailbox.beginTransaction(Mai lbox.java:1177)
at com.zimbra.cs.mailbox.Mailbox.getItemById(Mailbox. java:2044)
at com.zimbra.cs.mailbox.Mailbox.getFolderById(Mailbo x.java:2935)
at com.zimbra.cs.filter.IncomingMessageHandler.getDef aultFolderPath(IncomingMessageHandler.java:76)
at com.zimbra.cs.filter.RuleManager.applyRulesToIncom ingMessage(RuleManager.java:406)
at com.zimbra.cs.filter.RuleManager.applyRulesToIncom ingMessage(RuleManager.java:363)
at com.zimbra.cs.lmtpserver.ZimbraLmtpBackend.deliver MessageToLocalMailboxes(ZimbraLmtpBackend.java:524 )
at com.zimbra.cs.lmtpserver.ZimbraLmtpBackend.deliver (ZimbraLmtpBackend.java:336)
at com.zimbra.cs.lmtpserver.LmtpHandler.processMessag eData(LmtpHandler.java:371)
at com.zimbra.cs.lmtpserver.TcpLmtpHandler.continueDA TA(TcpLmtpHandler.java:74)
at com.zimbra.cs.lmtpserver.LmtpHandler.doDATA(LmtpHa ndler.java:356)
at com.zimbra.cs.lmtpserver.LmtpHandler.processComman d(LmtpHandler.java:172)
at com.zimbra.cs.lmtpserver.TcpLmtpHandler.processCom mand(TcpLmtpHandler.java:66)
at com.zimbra.cs.tcpserver.ProtocolHandler.processCon nection(ProtocolHandler.java:196)
at com.zimbra.cs.tcpserver.ProtocolHandler.run(Protoc olHandler.java:139)
at java.util.concurrent.ThreadPoolExecutor$Worker.run Task(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorEx ception: Unknown table engine 'InnoDB5?4'

Query being executed when exception was thrown:
SELECT mi.id, mi.type, mi.parent_id, mi.folder_id, mi.index_id, mi.imap_id, mi.date, mi.size, mi.volume_id, mi.blob_digest, mi.unread, mi.flags, mi.tags, mi.subject, mi.name, mi.metadata, mi.mod_metadata, mi.change_date, mi.mod_content FROM mboxgroup5.mail_item AS mi WHERE mailbox_id = 5 AND type IN (1,2,13,3)


Any suggestions?

Here's ~zimbra/conf/my.cnf:
====================

[mysqld]

slow_query_log_file = /opt/zimbra/log/myslow.log

slow_query_log = 1

plugin-load = innodb=ha_innodb_plugin.so;innodb_trx=ha_innodb_pl ugin.so;innodb_locks=ha_innodb_plugin.so;innodb_lo ck_waits=ha_innodb_plugin.so;innodb_cmp=ha_innodb_ plugin.so;innodb_cmp_reset=ha_innodb_plugin.so;inn odb_cmpmem=ha_innodb_plugin.so;innodb_cmpmem_reset =ha_innodb_plugin.so

ignore-builtin-innodb
;JB;innodb_force_recovery = 1


basedir = /opt/zimbra/mysql
datadir = /opt/zimbra/db/data
socket = /opt/zimbra/db/mysql.sock
pid-file = /opt/zimbra/db/mysql.pid
bind-address = localhost
port = 7306
user = zimbra
tmpdir = /opt/zimbra/data/tmp

external-locking

long-query-time = 1
log-queries-not-using-indexes

thread_cache_size = 110
max_connections = 110

# We do a lot of writes, query cache turns out to be not useful.
query_cache_type = 0

sort_buffer_size = 1048576
read_buffer_size = 1048576

# (Num mailbox groups * Num tables in each group) + padding
table_cache = 1200

innodb_buffer_pool_size = 1242461798
innodb_log_file_size = 104857600
innodb_log_buffer_size = 8388608
innodb_file_per_table

# Value is: 200 + max_connections + 2 * table_cache
innodb_open_files = 2710

innodb_max_dirty_pages_pct = 10
innodb_flush_method = O_DIRECT
innodb_flush_log_at_trx_commit = 0

[mysqld_safe]

err-log = /opt/zimbra/log/mysqld.log
pid-file = /opt/zimbra/db/mysql.pid

[uxbod]

Wow thats a cracker! Anything in the MySQL log file ? How much free resource is on the server ?

ps -e -orss=,args= | sort -r -b -k1,1n | pr -TW$COLUMNS | tail -10

[Jesster]

Originally Posted by uxbod

Wow thats a cracker! Anything in the MySQL log file ? How much free resource is on the server ?

[root@z ~]# free -m
             total       used       free     shared    buffers     cached
Mem:          3949       3542        406          0        256        922
-/+ buffers/cache:       2363       1586
Swap:         2047       1498        549
[root@z ~]#

I _think_ this is the relevant snippet from /opt/zimbra/log/mysql_error.log:

110208 16:32:49 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
110208 16:32:49  InnoDB: highest supported file format is Barracuda.
110208 16:32:50 InnoDB Plugin 1.0.13 started; log sequence number 4589074227
110208 16:32:50 [Note] Event Scheduler: Loaded 0 events
110208 16:32:50 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.52-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution
110208 17:52:42 mysqld_safe Number of processes running now: 0
110208 17:52:42 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
InnoDB: mmap(1269399552 bytes) failed; errno 12
InnoDB: Fatal error: cannot allocate the memory for the buffer pool
110208 17:52:44 [ERROR] Plugin 'InnoDB' init function returned error.
110208 17:52:44 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
110208 17:52:44 [Note] Event Scheduler: Loaded 0 events
110208 17:52:44 [Note] /opt/zimbra/mysql/libexec/mysqld: ready for connections.
Version: '5.1.52-log'  socket: '/opt/zimbra/db/mysql.sock'  port: 7306  Source distribution

[uxbod]

What is chewing up all of the memory ? What does a top show ?

ps -e -orss=,args= | sort -r -b -k1,1n | pr -TW$COLUMNS | tail -10

[Jesster]

Originally Posted by uxbod

What is chewing up all of the memory ? What does a top show ?

ps -e -orss=,args= | sort -r -b -k1,1n | pr -TW$COLUMNS | tail -10

Perhaps Amavis?


Top output:

top - 09:46:33 up 38 days, 21:52,  2 users,  load average: 0.05, 0.16, 0.17
Tasks: 180 total,   1 running, 179 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.3%us,  0.2%sy,  0.0%ni, 99.1%id,  0.4%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   4044472k total,  3626104k used,   418368k free,   262924k buffers
Swap:  2097144k total,  1534332k used,   562812k free,   948440k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                
22790 zimbra    18   0 2255m 769m 7060 S  0.0 19.5  36:20.69 java                                                                                                   
11481 zimbra    19   0  656m 312m 4632 S  0.0  7.9  20:44.03 java                                                                                                   
10936 zimbra    16   0  221m  70m 3880 S  0.0  1.8   0:49.77 amavisd                                                                                                
29008 zimbra    18   0  221m  70m 3928 S  0.0  1.8   0:04.36 amavisd                                                                                                
 8193 zimbra    15   0  221m  69m 3820 S  0.0  1.8   0:13.07 amavisd                                                                                                
15250 zimbra    17   0  221m  68m 3808 S  0.0  1.7   0:25.78 amavisd                                                                                                
19938 zimbra    15   0  221m  68m 3804 S  0.0  1.7   0:10.66 amavisd                                                                                                
20559 zimbra    18   0  220m  67m 3804 S  0.0  1.7   0:04.93 amavisd                                                                                                
 1185 zimbra    15   0  220m  67m 3788 S  0.0  1.7   0:03.70 amavisd                                                                                                
18357 zimbra    15   0  261m  54m 1460 S  0.0  1.4   0:48.57 clamd                                                                                                  
30390 zimbra    21   0  364m  14m 3456 S  0.0  0.4   2:09.73 slapd                                                                                                  
31434 zimbra    15   0  212m  14m  940 S  0.0  0.4   0:00.01 amavisd                                                                                                
 4831 zimbra    18   0  212m  14m  924 S  0.0  0.4   0:00.01 amavisd                                                                                                
 5360 zimbra    15   0  212m  14m  924 S  0.0  0.4   0:00.01 amavisd                                                                                                
11106 zimbra    15   0  160m  12m 1920 S  0.0  0.3   2:02.71 mysqld                                                                                                 
18204 zimbra    15   0  212m  11m  576 S  0.0  0.3   0:38.10 amavisd                                                                                                
 2748 zimbra    15   0 42864  10m  856 S  0.0  0.3   0:00.60 perl

Your command output:

[zimbra@z log]$ ps -e -orss=,args= | sort -r -b -k1,1n | pr -TW$COLUMNS | tail -10
55492 /opt/zimbra/clamav/sbin/clamd --config-file=/opt/zimbra/conf/clamd.conf
69296 amavisd (ch1-avail)
69408 amavisd (ch3-avail)
70156 amavisd (ch3-avail)
70268 amavisd (ch10-avail)
71192 amavisd (ch11-avail)
72272 amavisd (ch3-avail)
72472 amavisd (ch18-avail)
317904 /opt/zimbra/java/bin/java -XX:ErrorFile=/opt/zimbra/log -client -Xmx256m -Dzimbra.home=/opt/zimbra -Djava.library.path=/opt/zimbra/lib -Djava.ext.dirs=/opt/z
787816 /opt/zimbra/java/bin/java -server -Djava.awt.headless=true -Dsun.net.inetaddr.ttl=60 -XX:+UseConcMarkSweepGC -XX:PermSize=128m -XX:MaxPermSize=128m -XX:SoftR
[zimbra@z log]$