mysql uses 100% of my processing power

[Gerbrand]

on my zimbra system (debian using the latest 3.1.0 zimbra version, amd opteron 2 GHz, dedicated for zimbra) with currently just around 10 mailboxes and a throughput of a few hundred email messages per day, mysql uses 100% of my processing power.

i find this odd.

how can I check what mysql is doing?

zimbra@zimbra:~/db/data$ ~/mysql/bin/mysqladmin -P 7306 -S /opt/zimbra/db/mysql.sock status
Uptime: 3564 Threads: 3 Questions: 3167 Slow queries: 8 Opens: 21 Flush tables: 1 Open tables: 15 Queries per second avg: 0.889

top - 13:40:45 up 39 days, 19:00, 2 users, load average: 0.80, 0.77, 0.87
Tasks: 106 total, 2 running, 104 sleeping, 0 stopped, 0 zombie
Cpu(s): 65.4% us, 34.6% sy, 0.0% ni, 0.0% id, 0.0% wa, 0.0% hi, 0.0% si
Mem: 2077192k total, 2005096k used, 72096k free, 179124k buffers
Swap: 3903752k total, 64k used, 3903688k free, 1119872k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
5024 zimbra 16 0 92208 21m 3108 S 99.8 1.1 46:54.16 mysqld
9121 gerbrand 16 0 6520 1564 1072 R 0.3 0.1 0:00.22 sshd
1 root 16 0 1604 532 468 S 0.0 0.0 0:07.46 init

CPU usage since mailboxes start receiving email

[KevinH]

ps -ef | grep zimbra

Might want to se if log processing is causing this or something else. Also would be a good idea to check the 2 myslow logs for any hint to what slow queries are running on MySQL.

[Gerbrand]

Kevin, thanks,

I can't see anything special. Do you?

My myslow.log is empty. myslow.log logs from previous days have a size of around 2KB and show around 10 queries per day.

logger_myslow.log shows something like this (a similar line appears every few seconds)

# Time: 060508 18:56:23
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 75559
select distinct(host) from disk_aggregate where period_start >= '2006-04-25 00:00:00' and period_end <= '2006-04-26 00:00:00';
# Time: 060508 18:56:27
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 3 Lock_time: 0 Rows_sent: 1 Rows_examined: 98450
select avg(total) from disk_aggregate where host = 'zimbra.engagetv.com' and device = '/dev/sda8' and period_start >= '2006-04-25 00:00:00' and period_end <= '2006-04-26 00:00:00';
# Time: 060508 18:56:29
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 98450
select avg(available) from disk_aggregate where host = 'zimbra.engagetv.com' and device = '/dev/sda8' and period_start >= '2006-04-25 00:00:00' and period_end <= '2006-04-26 00:00:00';
# Time: 060508 18:56:31
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 98439
select avg(total) from disk_aggregate where host = 'zimbra.engagetv.com' and device = '/dev/sda6' and period_start >= '2006-04-25 00:00:00' and period_end <= '2006-04-26 00:00:00';

ps -ef | grep zimbra shows:

zimbra:/opt/zimbra/log# ps -ef | grep zimbra
zimbra 21579 1 0 May07 ? 00:00:00 /usr/bin/tail -n 0 -f /var/log/zimbra.log
zimbra 22416 1 0 May07 ? 00:00:00 /usr/bin/tail -n 0 -f /var/log/zimbra.log
zimbra 7574 1 0 05:04 ? 00:00:04 /opt/zimbra/openldap-2.3.20/libexec/slapd -l LOCAL0 -4 -u zimbra -h ldaps:// ldap://:389/ -f /opt/zimbra/conf/slapd.conf
zimbra 7719 1 0 05:04 ? 00:00:08 /usr/bin/perl /opt/zimbra/libexec/zmmtaconfig
zimbra 7893 1 0 05:04 ? 00:00:00 amavisd (master)
zimbra 8026 1 0 05:04 ? 00:00:00 /opt/zimbra/clamav/bin/freshclam --config-file=/opt/zimbra/conf/freshclam.conf -d --checks=12
zimbra 8033 1 0 05:04 ? 00:00:00 /bin/sh /opt/zimbra/logger/mysql/bin/mysqld_safe --defaults-file=/opt/zimbra/conf/my.logger.cnf --ledir=/opt/zimbra/logger/mysql/bin
zimbra 8065 8033 69 05:04 ? 09:45:56 /opt/zimbra/logger/mysql/bin/mysqld --defaults-file=/opt/zimbra/conf/my.logger.cnf --basedir=/opt/zimbra/logger/mysql --datadir=/opt/zimbra/logger/db/data --pid-file=/opt/zimbra/logger/db/mysql.pid --skip-locking --port=7307 --socket=/opt/zimbra/logger/db/mysql.sock
zimbra 8103 1 0 05:04 ? 00:00:03 /opt/zimbra/clamav/sbin/clamd --config-file /opt/zimbra/conf/clamd.conf
zimbra 8364 1 0 05:04 ? 00:00:22 /opt/zimbra/jdk1.5.0_06/bin/java -Xms608m -Xmx608m -client -XX:NewRatio=2 -Dcatalina.base=/opt/zimbra/apache-tomcat-5.5.15 -Dcatalina.home=/opt/zimbra/apache-tomcat-5.5.15 -Djava.io.tmpdir=/opt/zimbra/apache-tomcat-5.5.15/temp -Djava.library.path=/opt/zimbra/lib/jars -Djava.endorsed.dirs=/opt/zimbra/apache-tomcat-5.5.15/common/endorsed -classpath /opt/zimbra/apache-tomcat-5.5.15/bin/bootstrap.jar:/opt/zimbra/apache-tomcat-5.5.15/bin/commons-logging-api.jar org.apache.catalina.startup.Bootstrap start
zimbra 8368 1 0 05:04 ? 00:00:00 /bin/sh /opt/zimbra/mysql/bin/mysqld_safe --defaults-file=/opt/zimbra/conf/my.cnf --ledir=/opt/zimbra/mysql/bin
zimbra 8424 8368 0 05:04 ? 00:00:18 /opt/zimbra/mysql/bin/mysqld --defaults-file=/opt/zimbra/conf/my.cnf --basedir=/opt/zimbra/mysql --datadir=/opt/zimbra/db/data --pid-file=/opt/zimbra/db/mysql.pid --skip-locking --port=7306 --socket=/opt/zimbra/db/mysql.sock
root 8795 1 0 05:04 ? 00:00:00 /opt/zimbra/postfix-2.2.9/libexec/master
zimbra 8803 1 0 05:04 ? 00:00:00 /opt/zimbra/cyrus-sasl-2.1.21.ZIMBRA/sbin/saslauthd -r -a zimbra
zimbra 8808 8803 0 05:04 ? 00:00:00 /opt/zimbra/cyrus-sasl-2.1.21.ZIMBRA/sbin/saslauthd -r -a zimbra
zimbra 8809 8803 0 05:04 ? 00:00:00 /opt/zimbra/cyrus-sasl-2.1.21.ZIMBRA/sbin/saslauthd -r -a zimbra
zimbra 8810 8803 0 05:04 ? 00:00:00 /opt/zimbra/cyrus-sasl-2.1.21.ZIMBRA/sbin/saslauthd -r -a zimbra
zimbra 8815 8803 0 05:04 ? 00:00:00 /opt/zimbra/cyrus-sasl-2.1.21.ZIMBRA/sbin/saslauthd -r -a zimbra
zimbra 8823 1 0 05:04 ? 00:00:00 /opt/zimbra/httpd-2.0.54/bin/httpd -k start -f /opt/zimbra/conf/httpd.conf
zimbra 8824 8823 0 05:04 ? 00:00:00 /opt/zimbra/httpd-2.0.54/bin/httpd -k start -f /opt/zimbra/conf/httpd.conf
zimbra 8825 8823 0 05:04 ? 00:00:00 /opt/zimbra/httpd-2.0.54/bin/httpd -k start -f /opt/zimbra/conf/httpd.conf
zimbra 8826 8823 0 05:04 ? 00:00:00 /opt/zimbra/httpd-2.0.54/bin/httpd -k start -f /opt/zimbra/conf/httpd.conf
zimbra 8827 8823 0 05:04 ? 00:00:00 /opt/zimbra/httpd-2.0.54/bin/httpd -k start -f /opt/zimbra/conf/httpd.conf
zimbra 8828 8823 0 05:04 ? 00:00:00 /opt/zimbra/httpd-2.0.54/bin/httpd -k start -f /opt/zimbra/conf/httpd.conf
zimbra 22170 7893 0 17:42 ? 00:00:01 amavisd (ch4-avail)
zimbra 24328 7893 0 17:56 ? 00:00:00 amavisd (ch3-avail)
zimbra 25334 7893 0 18:03 ? 00:00:00 amavisd (ch3-avail)
zimbra 25411 7893 0 18:04 ? 00:00:01 amavisd (ch3-avail)
zimbra 26195 7893 0 18:08 ? 00:00:00 amavisd (ch3-avail)
zimbra 30368 7893 0 18:12 ? 00:00:00 amavisd (ch2-avail)
zimbra 30391 7893 0 18:13 ? 00:00:00 amavisd (ch2-avail)
zimbra 30938 7893 0 18:16 ? 00:00:00 amavisd (ch2-avail)
zimbra 31799 7893 0 18:21 ? 00:00:00 amavisd (ch2-avail)
zimbra 1697 7893 0 18:37 ? 00:00:00 amavisd (ch1-avail)
zimbra 5348 5347 0 19:00 ? 00:00:00 /bin/sh -c /opt/zimbra/libexec/zmlogprocess > /tmp/logprocess.out 2>&1
zimbra 5353 5348 0 19:00 ? 00:00:00 /usr/bin/perl /opt/zimbra/libexec/zmlogprocess
root 5617 3988 0 19:01 pts/0 00:00:00 grep zimbra

Do you see anything special?

Gerbrand

[KevinH]

Well the problem is logger. You can see it running here:

zimbra 5348 5347 0 19:00 ? 00:00:00 /bin/sh -c /opt/zimbra/libexec/zmlogprocess > /tmp/logprocess.out 2>&1
zimbra 5353 5348 0 19:00 ? 00:00:00 /usr/bin/perl /opt/zimbra/libexec/zmlogprocess

Did you do a big import or mail or are you getting lots of mail? One idea would be to disable the zmlogprocess from the cron task just to make sure things go back to normal. If your not getting much mail or doing an import you may have found a bug.

[Gerbrand]

Kevin,

thanks for the suggestion. I have disabled the logprocess, the cpu load is back to around 10%. Phew.

no I did not import any mail. The total amount of mail (for all mailboxes) is under 100 MB. And the amount of messages is less than a few hundred per day.

Concerning logging: Initially, so server statistics showed up in in the admin interface. As suggested in another posting on the forum, I added a 'server' in the admin interface. So I have 'zimbra' as well as 'zimbra.engagetv.com' listed as servers. Could this be the cause?

My mysql databases:
zimbra:/opt/zimbra/db/data# du -hs *

11M ibdata1
101M ib_logfile0
101M ib_logfile1
840K mailbox1
11M mailbox2
664K mailbox3
664K mailbox4
664K mailbox5
11M mailbox6
664K mailbox7
664K mailbox8
264K mysql
4.0K test
824K zimbra
12K zimbra-bin.000001
4.0K zimbra-bin.000002
72K zimbra-bin.000003
[...]

Should I check whether something is wrong with my database?

Gerbrand

[KevinH]

It seems ok but there must be something wrong with the log processor as it shouldn't be running much on a low traffic system.

[shankwc]

I think I have this problem too. After upgrading to 3.1 my CPU is consistently at 80-100%. I stopped the logger and it's back to less than 10%. I think this must be a bug.