Bug #33057 mysql command line client slows down and uses 100% CPU when restoring dump
Submitted: 7 Dec 2007 6:31 Modified: 8 Jan 2008 18:25
Reporter: Alexander Rubin
Status: Closed
Category:Client Severity:S3 (Non-critical)
Version:5.0.52,5.0.54 OS:Any
Assigned to: Daniel Fischer Target Version:5.0.56, 5.1.23, 6.0.5
Tags: mysql client, mysql command line client, regression
Triage: D1 (Critical)

[7 Dec 2007 6:31] Alexander Rubin
Description:
mysql command line client slows down significantly and uses 100% CPU when restoring dump
file. 
(extended inserts). After a while can crash.

mysql  Ver 14.12 Distrib 5.0.52, for redhat-linux-gnu (x86_64) using readline 5.1

Only affected mysql client (not server) in version 5.0.52, version 5.0.50 is fine.
mysql 5.0.52 is using readline 5.1 and mysql 5.0.50 is using readline 5.0

Tested with RedHat 4/5 and Ubuntu 7, 64bit

How to repeat:
mysqldump <db> <large_table_name> >dump.sql
(with mysql 5.0.52)
mysql <dump.sql

see process utilization with top and/or run strace
strace shows significant delays between reading data from disk

Suggested fix:
fix mysql command line client in 5.0.52
[7 Dec 2007 12:09] Shane Bester
i confirm this observation on 5.0.52-win32-noinstall package.
just using some 11GB dumpfile I created, the 5.0.52 could only read about 1MB per minute,
while the 5.0.50 mysql.exe could load at about 6MB per second!!
[7 Dec 2007 12:24] Shane Bester
maybe fix for bug #26215 is related?  I see nothing in the changelogs for this, btw..
[20 Dec 2007 16:00] Domas Mituzas
example regression file

Attachment: t1.sql (, text), 127.57 KiB.

[20 Dec 2007 16:02] Domas Mituzas
I attached extremely simple dump file, that illustrates the regression:

5.0.52 and later:

real    0m17.661s
user    0m15.417s
sys     0m1.880s

5.0.50:

real    0m0.380s
user    0m0.008s
sys     0m0.012s

do note, that it is just 100k line, at few megabytes client hangs for minutes, and I
guess, hours-per-query are also possible at reasonable packet sizes.
[20 Dec 2007 16:16] Domas Mituzas
oprofile:

8408     64.7317  vmlinux-debug-2.6.22-14-generic native_safe_halt
4135     31.8346  mysql                    add_line(String&, char*, char*, bool*)

so, nearly 100% execution is spent in add_line

This has been reproduced on Linux and MacOSX  systems.
[20 Dec 2007 19:21] Daniel Fischer
The regression is caused by this changeset. Unapplying it makes the problem go away:

ChangeSet@1.2521.66.1, 2007-11-02 13:40:34+03:00, kaa@polly.(none) +4 -0
  Fix for:
    bug #26215: mysql command line client should not strip comments
                from SQL statements
  and
    bug #11230: Keeping comments when storing stored procedures

Many thanks to Domas again for helping nail this down. :-)
[20 Dec 2007 21:41] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/40304

ChangeSet@1.2584, 2007-12-20 21:37:21+01:00, df@pippilotta.erinye.com +1 -0
  BUG#33057 mysql command line client slows down and uses 100% CPU when restoring dump
[22 Dec 2007 15:26] Bugs System
Pushed into 6.0.5-alpha
[22 Dec 2007 15:32] Bugs System
Pushed into 5.1.23-rc
[22 Dec 2007 15:37] Bugs System
Pushed into 5.0.56
[8 Jan 2008 18:25] Paul DuBois
Noted in 5.0.56, 5.1.23, 6.0.5 changelogs.

The fix for Bug#11230 and Bug#26215 introduced a significant
input-parsing slowdown for the mysql client. This has been corrected.
[9 Jan 2008 7:37] Valeriy Kravchuk
Bug #33757 was marked as a duplicate of this one.
[15 Feb 2008 5:40] Valeriy Kravchuk
Bug #34578 was marked as a duplicate of this one.
[7 Jan 23:28] Roel Van de Paar
For customers having this issue: you can use the command line client binary from 5.0.56.
[28 Aug 19:25] Gareth Evans
I can't find 5.0.56 in the archives... now using mysql.exe from 5.0.85 instead.
( noinstall version - http://dev.mysql.com/downloads/mysql/5.0.html#win32 )

Editing my.ini as described in this post:
http://www.mysql.com/news-and-events/newsletter/2003-11/a0000000269.html

...allowed me to get SQL-dumped imports running at about 20KB/s - better than ~2KB/s
before!

Hope that might help someone.
[8 Sep 13:03] James Day
Gareth, any later version is OK. You might also dynamically  set
innodb_max_dirty_pages_pct to 5 or 1 during the reload. Dirty page flushing often becomes
the performance bottleneck in large loads and setting innodb_max_dirty_pages_pct to a low
value causes the background thread to become more active sooner.

James Day, MySQL Senior Support Engineer, Sun Microsystems