[debian-mysql] Bug#646859: [mysql-server-5.1] check_for_crashed_tables() uses too much CPU time for each MyISAM table when MySQL starts (debian-start)?
Filipus Klutiero
chealer at gmail.com
Thu Oct 27 20:49:30 UTC 2011
Package: mysql-server-5.1
Version: 5.1.58-1
Severity: wishlist
Hi,
I'm opening a ticket about a general problem, but this is food for
thought too. Please apologize and triage as you wish.
I am a web developer working on a web application which has a large
schema. There are currently over 200 tables in the schema, all of them
MyISAM.
Every few weeks, I'll install a new version of the application and
create a new MySQL database for it.
My development desktop was installed in April 2010, and has been getting
slower and slower to boot, to the point where I'm thinking about
reinstalling since months. There is a lot of disk read during boot, and
I never knew precisely why. Today I realized by accident that mysqld was
taking about 10% CPU for a very long time during boot, and went to
investigate why.
Restarting mysql seems to happen fast (less than 5 seconds), but it was
in fact causing significant CPU usage for a long time. I found that this
CPU usage happened every time mysql was started, and then that this came
from /etc/mysql/debian-start. I then discovered it came from
check_for_crashed_tables(). The function contains:
> LC_ALL=C $MYSQL --skip-column-names --batch -e '
> select concat('\''select count(*) into @discard from `'\'',
> TABLE_SCHEMA, '\''`.`'\'', TABLE_NAME, '\''`'\'')
> from information_schema.TABLES where ENGINE='\''MyISAM'\' | \
> xargs -i $MYSQL --skip-column-names --silent --batch \
> --force -e "{}" >$tempfile
The function has the following description:
> ## Check all unclosed tables.
> # - Requires the server to be up.
> # - Is supposed to run silently in background.
It turns out that each table check takes a significant time, and when
you have many MyISAM tables, this can take a very long time. There are
7119 tables on my machine. Checking a small schema, like phpmyadmin's,
takes no time:
> # time LC_ALL=C /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf
> --skip-column-names --batch -e 'select concat('\''select count(*)
> into @discard from `'\'',TABLE_SCHEMA, '\''`.`'\'', TABLE_NAME,
> '\''`'\'') from information_schema.TABLES where
> TABLE_SCHEMA='\''phpmyadmin'\'' AND ENGINE='\''MyISAM'\' | xargs
> -i /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf
> --skip-column-names --silent --batch
>
> real 0m0.122s
> user 0m0.052s
> sys 0m0.040s
> root at vinci:/var/log#
Checking a large schema, like my application's, takes a noticeable time:
> # time LC_ALL=C /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf
> --skip-column-names --batch -e 'select concat('\''select count(*)
> into @discard from `'\'',TABLE_SCHEMA, '\''`.`'\'', TABLE_NAME,
> '\''`'\'') from information_schema.TABLES where
> TABLE_SCHEMA='\''tiki_8.0.beta'\'' AND ENGINE='\''MyISAM'\' |
> xargs -i /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf
> --skip-column-names --silent --batch
>
> real 0m2.784s
> user 0m1.256s
> sys 0m0.708s
> root at vinci:/var/log#
Checking several large schemas, as on my machine, takes a pretty long time:
> # time LC_ALL=C /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf
> --skip-column-names --batch -e 'select concat('\''select count(*)
> into @discard from `'\'',TABLE_SCHEMA, '\''`.`'\'', TABLE_NAME,
> '\''`'\'') from information_schema.TABLES where ENGINE='\''MyISAM'\'
> | xargs -i /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf
> --skip-column-names --silent --batch
>
> real 1m2.646s
> user 0m27.362s
> sys 0m16.145s
> root at vinci:/var/log#
Note that the databases are not big, they don't take 200 MB in total.
It's just checking any table seems to take a significant time. The
screenshot attached shows how the databases look.
So, my first question is whether this check can be optimized. The last
command suggests checking a table takes on average more than 1/200 of a
second of CPU time.
If not, I'm wondering if something could be done to alleviate the
problem. I'm annoyed by 2 things:
* This check is not needed for me. Of course, I'm on a development
machine...
* It took me a lot of time to disable the check.
On the first point, if I boot Debian 5 times today, MySQL will spend
some 5 minutes checking tables, even if no queries were run on MySQL.
This seems like a waste. Couldn't this check work in a way similar to
fsck and only check after either a given time or number of startups
(mounts) limit is reached?
If that is not possible, then I hope we could at least make it easier
for people to workaround. Once you understand what's wrong, fixing takes
no time, you just do a one character change to /etc/mysql/debian-start
(commenting line 29 "check_for_crashed_tables;"). There is even a
comment that hints to this problem in the file:
> # If you want to disable the check for crashed tables comment
> # "check_for_crashed_tables" out.
The problem is that one needs to find the problem first. There are 2
issues here: First, it took me a long time (I guess a year) to realize
that MySQL was causing such a CPU use. Then, it took me a considerable
time (roughly an hour) to figure out why.
On the second point, I started with /etc/init.d/mysql, then went to
/etc/mysql/debian-start and then went to
/usr/share/mysql/debian-start.inc.sh. I missed the comment hinting about
this issue in /etc/mysql/debian-start. That comment is embedded in a
paragraph, and not particularly obvious. So I went to read
check_for_crashed_tables(), which is not too clear (a call to xargs and
a check done implicitly by a read that relies on a configuration value
of myisam-recover...).
It would be nice if there could be something right in /etc/init.d/mysql
to tell about this issue. Perhaps a flag in an /etc/default/mysql.
It would be even better if the issue was obvious before even looking at
code. But the scripts don't make it obvious. Starting mysql seems to
happen very quickly:
> # time invoke-rc.d mysql start
> Starting MySQL database server: mysqld.
> Checking for tables which need an upgrade, are corrupt or were
> not closed cleanly..
>
> real 0m1.177s
> user 0m0.048s
> sys 0m0.064s
> root at vinci:/var/log#
If you then look at logs, there is no hint that the check too that long:
> Oct 27 16:24:56 vinci mysqld_safe: Starting mysqld daemon with
> databases from /var/lib/mysql
> Oct 27 16:24:56 vinci mysqld: 111027 16:24:56 [Note] Plugin
> 'FEDERATED' is disabled.
> Oct 27 16:24:56 vinci mysqld: 111027 16:24:56 InnoDB: Initializing
> buffer pool, size = 8.0M
> Oct 27 16:24:56 vinci mysqld: 111027 16:24:56 InnoDB: Completed
> initialization of buffer pool
> Oct 27 16:24:56 vinci mysqld: 111027 16:24:56 InnoDB: Started; log
> sequence number 0 1275545
> Oct 27 16:24:56 vinci mysqld: 111027 16:24:56 [Note] Event Scheduler:
> Loaded 0 events
> Oct 27 16:24:56 vinci mysqld: 111027 16:24:56 [Note] /usr/sbin/mysqld:
> ready for connections.
> Oct 27 16:24:56 vinci mysqld: Version: '5.1.58-1' socket:
> '/var/run/mysqld/mysqld.sock' port: 3306 (Debian)
> Oct 27 16:24:57 vinci /etc/mysql/debian-start[10974]: Upgrading MySQL
> tables if necessary.
> Oct 27 16:24:57 vinci /etc/mysql/debian-start[10977]:
> /usr/bin/mysql_upgrade: the '--basedir' option is always ignored
> Oct 27 16:24:57 vinci /etc/mysql/debian-start[10977]: Looking for
> 'mysql' as: /usr/bin/mysql
> Oct 27 16:24:57 vinci /etc/mysql/debian-start[10977]: Looking for
> 'mysqlcheck' as: /usr/bin/mysqlcheck
> Oct 27 16:24:57 vinci /etc/mysql/debian-start[10977]: This
> installation of MySQL is already upgraded to 5.1.58, use --force if
> you still need to run mysql_upgrade
> Oct 27 16:24:57 vinci /etc/mysql/debian-start[10984]: Checking for
> insecure root accounts.
> Oct 27 16:24:57 vinci /etc/mysql/debian-start[10988]: Triggering
> myisam-recover for all MyISAM tables
This all makes it look as if mysql was done starting after 2 seconds.
check_for_crashed_tables() logs "Triggering myisam-recover for all
MyISAM tables" before starting the check, but it doesn't log when it's
done. As it is the last startup step, there is no hint that the whole
startup actually took a lot longer.
Back to the first problem (not realizing that MySQL is slowing down the
boot), I regularly check how the boot goes, but I never noticed
anything, since the init script returns so fast when it starts. This
happens because the big tasks are run in the background. This is a
deliberate choice, as evidenced by these comments:
> # - Is supposed to run silently in background.
> # But do it in the background to not stall the boot process.
> # The following commands should be run when the server is up but in
> background
> # where they do not block the server start and in one shell instance
> so that
> # they run sequentially.
This was probably a great decision when it was made, as the check seems
to be CPU-intensive but very low on I/O, while the rest of the boot is
rather to the opposite, so this allowed a shorter total boot time.
However, now that we have a parallel boot sequence, backgrounding
processes shouldn't be needed to optimize CPU use. I think it's time to
reconsider whether backgrounding is warranted.
In the end, MySQL probably contributed little to the heavy I/O when I
boot, but I'm happy I found this problem anyway.
--- System information. ---
Architecture: i386
Kernel: Linux 3.0.0-2-amd64
Debian Release: wheezy/sid
990 testing security.debian.org
990 testing ftp.ca.debian.org
500 unstable ftp.ca.debian.org
1 experimental ftp.ca.debian.org
--- Package information. ---
Depends (Version) | Installed
=======================================-+-==============
mysql-client-5.1 (>= 5.1.58-1) | 5.1.58-1
libdbi-perl | 1.616-1+b1
perl (>= 5.6) | 5.12.4-6
libc6 (>= 2.7) | 2.13-21
libgcc1 (>= 1:4.1.1) | 1:4.6.1-15
libmysqlclient16 (>= 5.1.50-1) | 5.1.58-1
libstdc++6 (>= 4.1.1) | 4.6.1-15
zlib1g (>= 1:1.1.4) | 1:1.2.3.4.dfsg-3
debconf (>= 0.5) | 1.5.40
OR debconf-2.0 |
psmisc | 22.13-1
passwd | 1:4.1.4.2+svn3283-3
lsb-base (>= 3.0-10) | 3.2-28
mysql-server-core-5.1 (= 5.1.58-1) | 5.1.58-1
Recommends (Version) | Installed
====================================-+-===========
mailx |
libhtml-template-perl | 2.10-1
Suggests (Version) | Installed
=======================-+-===========
tinyca |
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.alioth.debian.org/pipermail/pkg-mysql-maint/attachments/20111027/a679bf25/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: databases.png
Type: image/png
Size: 184068 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-mysql-maint/attachments/20111027/a679bf25/attachment-0001.png>
More information about the pkg-mysql-maint
mailing list