LinHES Forums
http://forum.linhes.org/

mysql using 150% cpu
http://forum.linhes.org/viewtopic.php?f=21&t=21252		 Page 1 of 1
Author:  goofee [ Tue Jul 27, 2010 11:42 pm ]
Post subject:  mysql using 150% cpu
I got some new to me hardware. I did a fresh LinHES R6.01 install and restored my R5.5 DB, then upgraded to R6.03. I've been running it for about a month now and at times I find is slow to respond. top tells me that mysql is using 150% cpu usage. A quick restart of mysql and things are back to normal for a while. /var/log/mysql.log is blank so I'm not sure where to start looking. When I look at the RRD graphs it seems to happen around midnight. /etc/cron.daily has something in there to check the DB but when I run it manually it runs fine, and it doesn't happen every day.

Any thoughts on where to start?

Image
Image
Author:  manicmike [ Wed Jul 28, 2010 8:31 pm ]
Post subject:  Re: mysql using 150% cpu
goofee wrote:
/var/log/mysql.log is blank

From memory, that's not where mysqld's logs are. Look at /var/log/mysql/. Also, mysql logs may be binary (noticed a while ago that this was the case - may not be any longer). If so, you will have to use amysql log tool to read them.

I would tail -f the log file while the cpu is climbing.

Mike

EDIT: Just noticed that it seems to jump suddenly to 100% at midnight. Is that correct? It's highly suspicious. What cron jobs are running at midnight? What do the other logs say about this?
Author:  goofee [ Thu Jul 29, 2010 12:45 am ]
Post subject: 
Hi Mike.
Quote:
From memory, that's not where mysqld's logs are
Both my production box and test box have /var/log/mysqld.log files but they are blank. I don't see a mysql folder in the log folder either. I changed /etc/sv/mysql/run to point to /var/log/mysqld.log instead of /dev/null but all I get is this when the server starts. Nothing changes when it starts to run away.
Code:
100727 15:34:23 [Warning] option 'max_join_size': unsigned value 18446744073709551615 adjusted to 4294967295
100727 15:34:23 [Warning] option 'max_join_size': unsigned value 18446744073709551615 adjusted to 4294967295
100727 15:34:24  InnoDB: Started; log sequence number 0 2676041
100727 15:34:24 [Warning] 'user' entry 'root@masterbackend' ignored in --skip-name-resolve mode.
100727 15:34:24 [Warning] 'user' entry '@masterbackend' ignored in --skip-name-resolve mode.
100727 15:34:24 [Warning] 'user' entry 'mythtv@myhost' ignored in --skip-name-resolve mode.
100727 15:34:24 [Warning] 'db' entry 'mythconverg mythtv@myhost' ignored in --skip-name-resolve mode.
100727 15:34:24 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.0.75'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution

The thing I suspect, like you, is that since it's always happening near midnight that some job is setting it off, however it's not doing it every day. (6-7 times this month) The first suspect is /etc/cron.daily/myth_mtc.sh which appears to run an optimize on the db. The log from that is
Code:
/usr/LH/bin/myth_mtc.py:4: DeprecationWarning: The popen2 module is deprecated. Use the subprocess module.
  import sys,popen2
2010-07-28 00:02:02.429 Python Database Connection: Using connection settings from /root/.mythtv/config.xml
2010-07-28 00:02:02.487 Python Database Connection: Using connection settings from /root/.mythtv/config.xml
programs in use
Myth is NOT idle
programs in use
Myth is NOT idle
Myth is idle
Running optimize
REPAIR archiveitems
OPTIMIZE archiveitems
ANALYZE archiveitems
REPAIR callsignnetworkmap
OPTIMIZE callsignnetworkmap
ANALYZE callsignnetworkmap
REPAIR capturecard
OPTIMIZE capturecard
ANALYZE capturecard
 - more of the same -


The only difference I can see between the logs on a night when it happens is the "myth is not idle" part. But is seems that it waits till it is before running the optimize.

See anything in there that jumps out at you that I may have missed?
Author:  manicmike [ Thu Jul 29, 2010 7:31 pm ]
Post subject: 
goofee wrote:
Hi Mike.
Quote:
From memory, that's not where mysqld's logs are
Both my production box and test box have /var/log/mysqld.log files but they are blank. I don't see a mysql folder in the log folder either. I changed /etc/sv/mysql/run to point to /var/log/mysqld.log instead of /dev/null but all I get is this when the server starts. Nothing changes when it starts to run away.
Code:
100727 15:34:23 [Warning] option 'max_join_size': unsigned value 18446744073709551615 adjusted to 4294967295
100727 15:34:23 [Warning] option 'max_join_size': unsigned value 18446744073709551615 adjusted to 4294967295
100727 15:34:24  InnoDB: Started; log sequence number 0 2676041
100727 15:34:24 [Warning] 'user' entry 'root@masterbackend' ignored in --skip-name-resolve mode.
100727 15:34:24 [Warning] 'user' entry '@masterbackend' ignored in --skip-name-resolve mode.
100727 15:34:24 [Warning] 'user' entry 'mythtv@myhost' ignored in --skip-name-resolve mode.
100727 15:34:24 [Warning] 'db' entry 'mythconverg mythtv@myhost' ignored in --skip-name-resolve mode.
100727 15:34:24 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.0.75'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution

The thing I suspect, like you, is that since it's always happening near midnight that some job is setting it off, however it's not doing it every day. (6-7 times this month) The first suspect is /etc/cron.daily/myth_mtc.sh which appears to run an optimize on the db. The log from that is
Code:
/usr/LH/bin/myth_mtc.py:4: DeprecationWarning: The popen2 module is deprecated. Use the subprocess module.
  import sys,popen2
2010-07-28 00:02:02.429 Python Database Connection: Using connection settings from /root/.mythtv/config.xml
2010-07-28 00:02:02.487 Python Database Connection: Using connection settings from /root/.mythtv/config.xml
programs in use
Myth is NOT idle
programs in use
Myth is NOT idle
Myth is idle
Running optimize
REPAIR archiveitems
OPTIMIZE archiveitems
ANALYZE archiveitems
REPAIR callsignnetworkmap
OPTIMIZE callsignnetworkmap
ANALYZE callsignnetworkmap
REPAIR capturecard
OPTIMIZE capturecard
ANALYZE capturecard
 - more of the same -


The only difference I can see between the logs on a night when it happens is the "myth is not idle" part. But is seems that it waits till it is before running the optimize.

See anything in there that jumps out at you that I may have missed?


It certainly seems high in the likelihood stakes. Two easy things to check whether it's the cause:
1. Run the process manually (run in a terminal the line in your crontab that runs the job) and check it, or
2. comment it out of your crontab, ensuring it doesn't run for a while. This isn't going to kill your database. The optimisation thing wasn't even in the distro until recently, so if you determine that it's the problem, just disable it.

The first is much better if you're really impatient.

Mike
Author:  goofee [ Sat Aug 21, 2010 9:42 am ]
Post subject: 
I found that /etc/cron.daily/myth_mtc.sh was on the backend and both my frontend only machines. I removed it from the frontend machines hoping that if they were running at the same time they might conflict. It didn't help so I removed it from the backend as well. I've now been running 2 weeks without a hitch. The real question is, if it's installed by default, and no one else is having trouble, what's wrong with my machine? Is the DB corrupt?
Author:  christ [ Sun Aug 22, 2010 10:45 am ]
Post subject: 
Interesting. Until you pointed out I didn't know what was causing my master backend to occasionally have mysql running at 99% of CPU. I found myth_mtc still running today which doesn't seem right. I've commented out that cron job and I will see if I am more stable.
Page 1 of 1 All times are UTC - 6 hours
Powered by phpBB® Forum Software © phpBB Group
http://www.phpbb.com/