MySQL Bugs: #15811: extremely long time for mysql client to execute long INSERT

Bug #15811	extremely long time for mysql client to execute long INSERT
Submitted:	16 Dec 2005 12:52	Modified:	9 Aug 2006 20:21
Reporter:	Yoshiaki Tajika (Basic Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Charsets	Severity:	S5 (Performance)
Version:	5.0.19-BK, 5.0.15	OS:	Linux (Linux)
Assigned to:	Tomash Brechko	CPU Architecture:	Any

Description:
It takes extremely long time for mysql client tool to execute long INSERT statement. This occurs at 5.0.15, but not at 5.0.13 or 4.1.15.
I think this is a serious problem, because mysqldump creates very long 
INSERT statement. 

How to repeat:
mysql> use test;
drop table if exists t1;
create table t1(c1 char(10)) engine=myisam default charset=latin1;
insert into t1 values('1234567890');
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;

Now 16384 records there. Then, dump it, and load it again.
# mysqldump test t1 > temp.sql
# mysql test < temp.sql

At my PC, loading took about 60 sec with 5.0.15,
while it's <1 sec at 4.0.15.

Suggested fix:
I checked mysql.cc of 5.0.15, 5.0.13, and 4.0.15.
I found that my_strcasecmp() was add into add_line() at 5.0.15.
Calling my_strcasecmp many times maybe wastes time.
When I replace 'my_strcasecmp(...)' with '0' (i.e, false),
the problem goes away!!

Sorry. Not 4.0.15 but 4.1.15!!

Thank you for a problem report. I've tried to repeat with latest 5.0-BK build, and saw nothing similar to your 60 seconds, on my old Celeron 300 MHz:

mysql> select version();
+-----------+
| version() |
+-----------+
| 4.1.17    |
+-----------+
1 row in set (0.00 sec)

mysql> drop table if exists t1;
Query OK, 0 rows affected (0.06 sec)

mysql> create table t1(c1 char(10)) engine=myisam default charset=latin1;
Query OK, 0 rows affected (0.01 sec)

mysql> insert into t1 values('1234567890');
Query OK, 1 row affected (0.00 sec)

mysql> insert into t1 select * from t1;
Query OK, 1 row affected (0.00 sec)
Records: 1  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 4 rows affected (0.00 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 8 rows affected (0.00 sec)
Records: 8  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 16 rows affected (0.00 sec)
Records: 16  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 32 rows affected (0.00 sec)
Records: 32  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 64 rows affected (0.00 sec)
Records: 64  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 128 rows affected (0.01 sec)
Records: 128  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 256 rows affected (0.01 sec)
Records: 256  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 512 rows affected (0.00 sec)
Records: 512  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 1024 rows affected (0.01 sec)
Records: 1024  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 2048 rows affected (0.02 sec)
Records: 2048  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 4096 rows affected (0.03 sec)
Records: 4096  Duplicates: 0  Warnings: 0

mysql> insert into t1 select * from t1;
Query OK, 8192 rows affected (0.05 sec)
Records: 8192  Duplicates: 0  Warnings: 0

mysql> exit
Bye
[openxs@Fedora 4.1]$ bin/mysqldump -uroot test t1 >/tmp/temp.sql
[openxs@Fedora 4.1]$ time bin/mysql -uroot test </tmp/temp.sql

real    0m0.500s
user    0m0.100s
sys     0m0.020s
[openxs@Fedora 4.1]$ bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 4 to server version: 4.1.17

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> select count(*) from t1;
+----------+
| count(*) |
+----------+
|    16384 |
+----------+
1 row in set (0.00 sec)

mysql> exit
Bye
[openxs@Fedora 4.1]$ bin/mysqladmin -uroot shutdown
STOPPING server from pid file /home/openxs/dbs/4.1/var/Fedora.pid
051217 16:12:40  mysqld ended

[1]+  Done                    bin/mysqld_safe
[openxs@Fedora 4.1]$ cd ../5.0/
[openxs@Fedora 5.0]$ bin/mysqld_safe &
[1] 22057
[openxs@Fedora 5.0]$ Starting mysqld daemon with databases from /home/openxs/dbs/5.0/var

[openxs@Fedora 5.0]$ time bin/mysql -uroot test </tmp/temp.sql

real    0m1.465s
user    0m0.120s
sys     0m0.060s
[openxs@Fedora 5.0]$ bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2 to server version: 5.0.18

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> select count(*) from t1;
+----------+
| count(*) |
+----------+
|    16384 |
+----------+
1 row in set (0.00 sec)

mysql> exit
Bye
[openxs@Fedora 5.0]$ uname -a
Linux Fedora 2.4.22-1.2115.nptl #1 Wed Oct 29 15:42:51 EST 2003 i686 i686 i386 GNU/Linux

It was a bit slower on 5.0.18, but not 60 times slower. About 1 second in both cases. So, please, check once more. With 5.0.16. Or wait till Monday and try with 5.0.17. it should be released officially next week.

Would you please try it like this?
# mysql test --default-character-set=ujis < temp.sql

As far as I tried,
a) --default-character-set latin1, utf8, and sjis are fast, 
   but ujis, big5, and gbk are slow.
b) Server side characterset defined in /etc/my.cnf has nothing 
   to do with this problem.
c) While I'm waiting, linux 'top' command shows that 
    mysql client tool's CPU% is over 95%.
d) 5.0.16 source build version has same result.

Thank you for the additional information. Please, try to repeat on 5.0.17. It is officially released already.

5.0.17 causes same problem, my co-worker says. I mean it's not only me who confronted this problem.
By the way did you try the command I showed previously?
# mysql test --default-character-set=ujis < temp.sql
If you can't reproduce it even with "--default-character-set=ujis",
it's me who should investigate further more. Please tell me your result.

Thank you for your persistency. I've tried with newest 5.0.19-BK (ChangeSet@1.1999, 2005-12-21 18:50:06+01:00), with the same amount of data, on the same Linux machine, and got:

[openxs@Fedora 5.0]$ time bin/mysql --default-character-set=ujis -uroot test </tmp/temp.sql

real    5m35.999s
user    5m35.040s
sys     0m0.020s

So, yes, there is a problem to solve, really.

Tomash, please keep in mind that this is somewhere in charsets code: Bar might give you a hint  where exactly

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/8058

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/8085

Pushed into 5.0 tree, currently tagged 5.0.23

Merged into 5.1.12

Noted in 5.0.23, 5.1.12 changelogs.

Long multiple-row INSERT statements could take a very long time for
some multi-byte character sets.