Bug #57153 Performance of call to POWER(LOG(EXP(0.25)),0.5) slower than expected on 5.1.51

• Submitted: 30 Sep 2010 20:32
• Modified: 11 Feb 2018 13:02
• Reporter: Max Crowe
• Status: Can't repeat
• Category: MySQL Server: DML
• Severity: S5 (Performance)
• Version: 5.1.51
• OS: Other (Centos 5.5)
• CPU Architecture: Any
• Tags: exp, log, power

[30 Sep 2010 20:32] Max Crowe

Description:
This may seem like a very obscure issue, but it did slow down some production code enough to cause me to have to take a look.  Upon noticing that a certain statement I was trying to run took much longer than expected on a server running MySQL 5.1.51 than it did on a server running 5.0.51, I narrowed the performance issue down to a function call to POWER(LOG(EXP(0.25)),0.5).

In the following test scenarios, the table tmp_speedtest has the following definition:

mysql> show create table tmp_speedtest;
+---------------+------------------------------------------------------------------------------------------------+
| Table         | Create Table                                                                                   |
+---------------+------------------------------------------------------------------------------------------------+
| tmp_speedtest | CREATE TABLE `tmp_speedtest` (
  `val` float DEFAULT NULL
) ENGINE=MyISAM DEFAULT CHARSET=utf8 |
+---------------+------------------------------------------------------------------------------------------------+

It contains 50000 rows.

This is what happens on a server with a 1x4 core Xeon E5520 2.26 Ghz CPU and 48 GB of RAM running Centos 5.5 and MySQL 5.1.51:

mysql> update tmp_speedtest set val=power(log(exp(0.25)),0.5);
Query OK, 50000 rows affected (1 min 59.93 sec)
Rows matched: 50000  Changed: 50000  Warnings: 0

If I use SQRT() instead of POWER(n,0.5), it runs very quickly:

mysql> update tmp_speedtest set val=sqrt(log(exp(0.25)));
Query OK, 0 rows affected (0.02 sec)
Rows matched: 50000  Changed: 0  Warnings: 0

If I change the parameter passed to EXP() or the power to which I take the resulting value, it also runs very quickly:

mysql> update tmp_speedtest set val=power(log(exp(0.26)),0.5);
Query OK, 50000 rows affected (0.11 sec)
Rows matched: 50000  Changed: 50000  Warnings: 0

mysql> update tmp_speedtest set val=power(log(exp(0.25)),0.3);
Query OK, 50000 rows affected (0.10 sec)
Rows matched: 50000  Changed: 50000  Warnings: 0

On a server with 2x2 core Opteron 2.6 Ghz CPUs and 32 GB of RAM running Fedora Core6 and MySQL 5.0.51, all of these statements run quickly:

mysql> update tmp_speedtest set val=power(log(exp(0.25)),0.5);
Query OK, 50000 rows affected (0.13 sec)
Rows matched: 50000  Changed: 50000  Warnings: 0

mysql> update tmp_speedtest set val=power(log(exp(0.26)),0.5);
Query OK, 50000 rows affected (0.14 sec)
Rows matched: 50000  Changed: 50000  Warnings: 0

mysql> update tmp_speedtest set val=power(log(exp(0.25)),0.3);
Query OK, 50000 rows affected (0.18 sec)
Rows matched: 50000  Changed: 50000  Warnings: 0

mysql> update tmp_speedtest set val=power(log(exp(0.25)),0.5);
Query OK, 50000 rows affected (0.14 sec)
Rows matched: 50000  Changed: 50000  Warnings: 0

mysql> update tmp_speedtest set val=sqrt(log(exp(0.25)));
Query OK, 0 rows affected (0.02 sec)
Rows matched: 50000  Changed: 0  Warnings: 0

This only appears to happen when running a SELECT or an UPDATE that causes many rows to be affected; running a large number of single SELECT statements with a call to this function resulted in similar performance on the two environments.

How to repeat:
Execute an UPDATE statement, or run an INSERT/SELECT statement, involving a call to POWER(LOG(EXP(0.25)),0.5), either on its own or embedded in some larger expression, which affects a large number of rows.

Suggested fix:
Cause POWER(LOG(EXP(0.25)),0.5) to be comparably efficient with variations on the same expression; for example, SQRT(LOG(EXP(0.25))).

[1 Oct 2010 13:01] Valeriy Kravchuk

I do not see the real difference of mysql-5.1 (current bzr tree) vs mysql-5.0 (current bzr tree):

macbook-pro:5.1 openxs$ bin/mysql -uroot testReading 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 1
Server version: 5.1.52-debug Source distribution

Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved.
This software comes with ABSOLUTELY NO WARRANTY. This is free software,
and you are welcome to modify and redistribute it under the GPL v2 license

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> CREATE TABLE `tmp_speedtest` (
    ->   `val` float DEFAULT NULL
    -> ) ENGINE=MyISAM;
Query OK, 0 rows affected (0.05 sec)

mysql> insert into tmp_speedtest values (0.0);
Query OK, 1 row affected (0.00 sec)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

mysql> insert into tmp_speedtest select * from tmp_speedtest;
Query OK, 32768 rows affected (0.11 sec)
Records: 32768  Duplicates: 0  Warnings: 0

mysql>  update tmp_speedtest set val=power(log(exp(0.25)),0.5);
Query OK, 65536 rows affected (0.59 sec)
Rows matched: 65536  Changed: 65536  Warnings: 0

mysql>  update tmp_speedtest set val=sqrt(log(exp(0.25)));
Query OK, 0 rows affected (0.07 sec)
Rows matched: 65536  Changed: 0  Warnings: 0

mysql>  update tmp_speedtest set val=power(log(exp(0.26)),0.5);
Query OK, 65536 rows affected (0.59 sec)
Rows matched: 65536  Changed: 65536  Warnings: 0

mysql>  update tmp_speedtest set val=power(log(exp(0.25)),0.3);
Query OK, 65536 rows affected (0.61 sec)
Rows matched: 65536  Changed: 65536  Warnings: 0

mysql> exit

Now compare to this, on the same hardware:

macbook-pro:5.0 openxs$ 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 1
Server version: 5.0.92-debug Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> CREATE TABLE `tmp_speedtest` (   `val` float DEFAULT NULL ) ENGINE=MyISAM;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into tmp_speedtest values (0.0);Query OK, 1 row affected (0.00 sec)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

mysql> insert into tmp_speedtest select * from tmp_speedtest;
Query OK, 32768 rows affected (0.09 sec)
Records: 32768  Duplicates: 0  Warnings: 0

mysql>  update tmp_speedtest set val=power(log(exp(0.25)),0.5);
Query OK, 65536 rows affected (0.55 sec)
Rows matched: 65536  Changed: 65536  Warnings: 0

mysql>  update tmp_speedtest set val=sqrt(log(exp(0.25)));
Query OK, 0 rows affected (0.06 sec)
Rows matched: 65536  Changed: 0  Warnings: 0

mysql>  update tmp_speedtest set val=power(log(exp(0.26)),0.5);
Query OK, 65536 rows affected (0.51 sec)
Rows matched: 65536  Changed: 65536  Warnings: 0

mysql>  update tmp_speedtest set val=power(log(exp(0.25)),0.3);
Query OK, 65536 rows affected (0.54 sec)
Rows matched: 65536  Changed: 65536  Warnings: 0

sqrt() runs faster than power(...,0.5) - that's all I can see in my tests.

[5 Oct 2010 17:50] MySQL Verification Team

Like Valeriy I couldn't repeat on Windows 64-bit. Are you able to test on another machine?. Thanks in advance.

[6 Nov 2010 0:14] Bugs System

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

[11 Feb 2018 13:02] Roy Lyseng

Posted by developer:
 
Closing as bug has been suspended for 7 years.