1

I have a problem with mysql killing the CPU on a Debian Squeeze 64. This is a development machine on a VPS so I stopped all the other services, including apache2. The mysql version is 5.1.49. This is the log when mysql starts : 

Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld_safe: Starting mysqld daemon with databases from /var/lib/mysql
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: 130206 19:03:40 [Note] Plugin 'FEDERATED' is disabled.
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: InnoDB: 1 transaction(s) which must be rolled back or cleaned up
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: InnoDB: in total 1 row operations to undo
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: InnoDB: Trx id counter is 0 31809536
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: 130206 19:03:40  InnoDB: Started; log sequence number 2 892018402
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: 130206 19:03:40 [Note] Event Scheduler: Loaded 0 events
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: 130206 19:03:40 [Note] /usr/sbin/mysqld: ready for connections.
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: Version: '5.1.49-3-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Debian)
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: InnoDB: Starting in background the rollback of uncommitted transactions
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: InnoDB: Cleaning up trx with id 0 2218455
Feb  6 19:03:40 Debian-60-squeeze-64-LAMP mysqld: 130206 19:03:40  InnoDB: Rollback of non-prepared transactions completed
Feb  6 19:03:41 Debian-60-squeeze-64-LAMP /etc/mysql/debian-start[4616]: Upgrading MySQL tables if necessary.
Feb  6 19:03:41 Debian-60-squeeze-64-LAMP /etc/mysql/debian-start[4619]: /usr/bin/mysql_upgrade: the '--basedir' option is always ignored
Feb  6 19:03:41 Debian-60-squeeze-64-LAMP /etc/mysql/debian-start[4619]: Looking for 'mysql' as: /usr/bin/mysql
Feb  6 19:03:41 Debian-60-squeeze-64-LAMP /etc/mysql/debian-start[4619]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
Feb  6 19:03:41 Debian-60-squeeze-64-LAMP /etc/mysql/debian-start[4619]: This installation of MySQL is already upgraded to 5.1.49, use --force if you still need to run mysql_upgrade
Feb  6 19:03:41 Debian-60-squeeze-64-LAMP /etc/mysql/debian-start[4626]: Checking for insecure root accounts.
Feb  6 19:03:41 Debian-60-squeeze-64-LAMP /etc/mysql/debian-start[4630]: Triggering myisam-recover for all MyISAM tables

The instant I start mysql the CPU goes skyhigh even though there are no queries running. This is the output of /etc/init.d/mysql status :

Server version          5.1.49-3-log
Protocol version        10
Connection              Localhost via UNIX socket
UNIX socket             /var/run/mysqld/mysqld.sock
Uptime:                 29 min 38 sec

Threads: 1  Questions: 955  Slow queries: 0  Opens: 5512  Flush tables: 1  Open tables: 32  Queries per second avg: 0.537.

Using strace on the mysql pid that uses 100% of the CPU I get something like this in just 1 or 2 minutes :

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
90.89  126.423901      179579       704           select
4.01    5.572348     2786174         2           rt_sigtimedwait
2.99    4.164260      118979        35         1 futex
2.11    2.929960           1   3471808           gettimeofday
0.00    0.000000           0         3         1 read
0.00    0.000000           0         3           write
0.00    0.000000           0         1           close
0.00    0.000000           0         4           rt_sigprocmask
0.00    0.000000           0         1         1 access
0.00    0.000000           0         6           sched_yield
0.00    0.000000           0         1           alarm
0.00    0.000000           0         1           accept
0.00    0.000000           0         1           shutdown
0.00    0.000000           0         1           getsockname
0.00    0.000000           0         2         1 setsockopt
0.00    0.000000           0         7           fcntl
0.00    0.000000           0         1           tgkill
------ ----------- ----------- --------- --------- ----------------
100.00  139.090469               3472581         4 total

The actual calls look like this :

19:37:26.553922 gettimeofday({1360175846, 553939}, NULL) = 0 <0.000004>
19:37:26.622537 gettimeofday({1360175846, 622591}, NULL) = 0 <0.000011>
19:37:26.622659 gettimeofday({1360175846, 622679}, NULL) = 0 <0.000009>
19:37:26.622737 gettimeofday({1360175846, 622754}, NULL) = 0 <0.000009>
19:37:26.622812 gettimeofday({1360175846, 622829}, NULL) = 0 <0.000008>
19:37:26.622887 gettimeofday({1360175846, 622951}, NULL) = 0 <0.000010>
19:37:26.623010 gettimeofday({1360175846, 623028}, NULL) = 0 <0.000008>
19:37:26.623109 gettimeofday({1360175846, 623132}, NULL) = 0 <0.000009>

I assume 3471808 calls to gettimeofday is the issue, but how do I fix it ? This happens everytime I start mysql, I even tried rebooting the server.

Thank you !

Additional info as requested :

Output of SHOW PROCESSLIST 

mysql> SHOW PROCESSLIST;
+-----+------+-----------+------+---------+------+-------+------------------+
| Id  | User | Host      | db   | Command | Time | State | Info             |
+-----+------+-----------+------+---------+------+-------+------------------+
| 325 | root | localhost | NULL | Query   |    0 | NULL  | SHOW PROCESSLIST |
+-----+------+-----------+------+---------+------+-------+------------------+
1 row in set (0.00 sec)

Output of top -H :

top - 21:21:26 up  5:35,  2 users,  load average: 1.07, 1.02, 1.00
Tasks: 152 total,   2 running, 150 sleeping,   0 stopped,   0 zombie
Cpu(s): 96.2%us,  1.9%sy,  0.0%ni,  0.0%id,  0.0%wa,  1.9%hi,  0.0%si,  0.0%st
Mem:   2061536k total,   973540k used,  1087996k free,    44952k buffers
Swap:  2102552k total,        0k used,  2102552k free,   693716k cached
noru
  • 121
  • 4
  • What does `SHOW PROCESS LIST` say? – longneck Feb 06 '13 at 19:59
  • output of SHOW PROCESSLIST : mysql> SHOW PROCESSLIST; +-----+------+-----------+------+---------+------+-------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----+------+-----------+------+---------+------+-------+------------------+ | 324 | root | localhost | NULL | Query | 0 | NULL | SHOW PROCESSLIST | +-----+------+-----------+------+---------+------+-------+------------------+ 1 row in set (0.00 sec) – noru Feb 06 '13 at 20:02
  • `strace` only shows system calls. Lots of things usually happen in between each system call. Is the 100% CPU in system or user space? – Ladadadada Feb 06 '13 at 20:02
  • At a stretch the host clock changed backwards and the `select` function is widely spinning until the clock has reached the same timestamp. Verify the system time and at least manually resync to a reliable source before starting. – Steve-o Feb 06 '13 at 20:04
  • User space I guess ? Output of top : `top -H top - 21:04:23 up 5:18, 2 users, load average: 1.26, 1.16, 1.04 Tasks: 151 total, 2 running, 149 sleeping, 0 stopped, 0 zombie Cpu(s): 96.3%us, 1.9%sy, 0.0%ni, 0.0%id, 0.0%wa, 1.9%hi, 0.0%si, 0.0%st Mem: 2061536k total, 972524k used, 1089012k free, 44736k buffers Swap: 2102552k total, 0k used, 2102552k free, 693684k cached` – noru Feb 06 '13 at 20:05
  • @Steve-o : The server was/is running ntp and the output of date seems correct : Wed Feb 6 21:06:46 CET 2013 – noru Feb 06 '13 at 20:08
  • I ended up dropping all the databases and rebooting the whole server again, all that is left is mysql and information_schema. Unfortunately still the same behavior. – noru Feb 06 '13 at 22:25

3 Answers3

1

I couldn't come up with anything else so in the end I had to reinstall the mysql server, which took care of the problem, after restoring the databases from backups everything runs smoothly now.

noru
  • 121
  • 4
0

I had a somewhat similar issue in which MySQL 5.1 on Debian Squeeze (32 bit) went to 100% CPU at times (not all the time) but didn't have time to diagnose it very much, as it was a few days before a key deadline.

Details

There were several different ways of getting the high-CPU issue in MySQL, I found.

Simplest way to reproduce was to run a specific Django admin view (standard admin UI page) that joins a few tables and returns a few thousand rows - this put one thread into 99% CPU reliably. Killing that thread stopped the issue.

mysql> show processlist;
+----+------------+-----------+-----------+---------+------+------------+-------------------------------------------------------------------------------------------------------+
| Id | User       | Host      | db        | Command | Time | State      | Info                                                                                                    |
+----+------------+-----------+-----------+---------+------+------------+-----------------------------------------------------------------------------------------------------+
| 68 | djangouser | localhost | django_db | Query   |   77 | statistics | SELECT `mytable`.`id`, `mytable`.`tenant_id`, `mytable |
| 69 | djangouser | localhost | django_db | Query   |    0 | NULL       | show processlist                                                                                     |
+----+------------+-----------+-----------+---------+------+------------+------------------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)

Related

https://groups.google.com/forum/?fromgroups=#!topic/django-users/Iz6x7c0i9nI Very similar case where hang occurred in Django queryset.

somewhat similar cases:

https://dba.stackexchange.com/questions/24643/mysql-5-5-runs-out-of-memory-drops-all-connections-when-creating-many-databases dba.stackexchange - MySQL drops all connections after creating 2,000 to 5,000 databases

https://groups.google.com/forum/?fromgroups=#!topic/django-users/sU-zj7s8uU4 - Non-terminating query optimizer on certain Django admin queries, due to 20 inner joins! Fix was setting optimizer_search_depth to 3 (default 62)

My solution - switch to PostgreSQL

Django made it very easy to switch to PostgreSQL through configuration only, plus the time to install and configure PostgreSQL - I realise this may not be an option for you, but if your language/framework makes it easy to switch, do seriously consider it. I used the default postgres packages in Debian 6.0 Squeeze which are fine - or you could use 9.1 or 9.2 packages for Debian from the Postgres project, which might be better and are much more recent.

The switchover only took a couple of hours, despite not having used PostgreSQL before, and got rid of this problem without creating new ones. And PostgreSQL has many other nice features, such that I'm now very glad I switched.

Until this point I didn't have strong views about MySQL vs PostgreSQL but now I would only use the latter.

Community
  • 1
RichVel
  • 3,554
  • 1
  • 18
  • 23
-2

I had the same issue. It was caused by a typo, instead of:

innodb_buffer_pool_size = 256M

I wrote

innodb_buffer_pool_size = 256M
MatthiasR
  • 1