| Bug #49141 | Encode function is significantly slower in 5.1 compared to 5.0 | ||
|---|---|---|---|
| Submitted: | 26 Nov 2009 15:31 | Modified: | 12 Mar 2010 16:42 |
| Reporter: | Oli Sennhauser | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: General | Severity: | S3 (Non-critical) |
| Version: | 5.1 | OS: | Any |
| Assigned to: | Davi Arnaut | CPU Architecture: | Any |
| Tags: | encode, performance, regression | ||
[26 Nov 2009 15:38]
Valeriy Kravchuk
Same on Mac OS X with 5.0.89 vs 5.1.42:
77-52-12-228: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.89-debug Source distribution
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> select benchmark(1000000,encode('hello','goodbye'));
+----------------------------------------------+
| benchmark(1000000,encode('hello','goodbye')) |
+----------------------------------------------+
| 0 |
+----------------------------------------------+
1 row in set (0.37 sec)
mysql> select benchmark(1000000,encode('hello','goodbye'));
+----------------------------------------------+
| benchmark(1000000,encode('hello','goodbye')) |
+----------------------------------------------+
| 0 |
+----------------------------------------------+
1 row in set (0.37 sec)
mysql> select benchmark(10000000,encode('hello','goodbye'));
+-----------------------------------------------+
| benchmark(10000000,encode('hello','goodbye')) |
+-----------------------------------------------+
| 0 |
+-----------------------------------------------+
1 row in set (3.73 sec)
mysql> exit
Bye
77-52-12-228:5.0 openxs$ bin/mysqladmin -uroot shutdown
STOPPING server from pid file /Users/openxs/dbs/5.0/var/77-52-12-148.dialup.umc.net.ua.pid
091126 15:33:59 mysqld ended
Compare to these:
77-52-12-228:5.1 openxs$ bin/mysql -uroot test
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.42-debug Source distribution
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> select benchmark(10000000,encode('hello','goodbye'));
+-----------------------------------------------+
| benchmark(10000000,encode('hello','goodbye')) |
+-----------------------------------------------+
| 0 |
+-----------------------------------------------+
1 row in set (2 min 47.59 sec)
mysql> select benchmark(1000000,encode('hello','goodbye'));
+----------------------------------------------+
| benchmark(1000000,encode('hello','goodbye')) |
+----------------------------------------------+
| 0 |
+----------------------------------------------+
1 row in set (18.20 sec)
So, it looks like a serious performance regression.
[2 Dec 2009 13:39]
Georgi Kodinov
This is the effect of implementing Bug #22684. Here's the 5.1 gprof: % cumulative self self total time seconds seconds calls s/call s/call name 92.72 15.40 15.40 261000051 0.00 0.00 my_rnd 5.36 16.29 0.89 1000000 0.00 0.00 SQL_CRYPT::SQL_CRYPT(char const*, unsigned int) 1.32 16.51 0.22 1000012 0.00 0.00 randominit 0.48 16.59 0.08 1000000 0.00 0.00 hash_password 0.06 16.60 0.01 1000000 0.00 0.00 Item_func_encode::val_str(String*) 0.06 16.61 0.01 1000000 0.00 0.00 SQL_CRYPT::encode(char*, unsigned int) 0.00 16.61 0.00 2000000 0.00 0.00 Item_string::val_str(String*) 0.00 16.61 0.00 1000000 0.00 0.00 copy_if_not_alloced(String*, String*, unsigned int) 0.00 16.61 0.00 1000000 0.00 0.00 Item_str_func::result_type() const ... Here's the 5.0 gprof: % cumulative self self total time seconds seconds calls ms/call ms/call name 96.97 0.32 0.32 5000303 0.00 0.00 my_rnd 1.52 0.33 0.01 1000000 0.00 0.00 Item_str_func::result_type() const 1.52 0.33 0.01 Item_func_set_collation::fix_length_and_dec() 0.00 0.33 0.00 1000000 0.00 0.00 copy_if_not_alloced(String*, String*, unsigned int) 0.00 0.33 0.00 1000000 0.00 0.00 Item_string::val_str(String*) 0.00 0.33 0.00 1000000 0.00 0.00 Item_func_encode::val_str(String*) 0.00 0.33 0.00 1000000 0.00 0.00 SQL_CRYPT::encode(char*, unsigned int) ...... Before this fix (in plan 5.0) the password can only be a constant string literal. Because of this you don't have to initialize the random structures for the password each time (as it's done at compile time). This raises the my_rnd calls from 5 millions to 261 millions.
[2 Dec 2009 15:09]
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/92484 3237 Georgi Kodinov 2009-12-02 Bug #49141: Encode function is significantly slower in 5.1 compared to 5.0 The fix for bug 22684 moved all the calculations to run time. For some special cases (e.g. a constant password) it's greatly beneficial to initialize the random structures at compile time and only calculate the outcome of the operation at run time. Implemented such caching of the random structures initialization. Fixed both ENCODE() and DECODE() functions.
[3 Dec 2009 20:58]
Davi Arnaut
For future reference: the slowdown happens when a ENCODE or DECODE function is evaluated multiple times within the execution of a statement. In 5.0, the function would be initialized once at parsing time and evaluating didn't require the function to be initialized. In 5.1, the initialization was moved to runtime and needs to be performed each time the function is evaluated.
Hence, there is now slowdown for the simple case where the function is called directly and only once (ie: SELECT ENCODE('a','b')). The slowdown happens when the function is evaluated multiple times -- for example, within a BENCHMARK function, prepared statement, stored procedure, subquery or multiple rows in SELECT.
[4 Dec 2009 15:07]
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/92896 3244 Davi Arnaut 2009-12-04 Bug#49141: Encode function is significantly slower in 5.1 compared to 5.0 The problem was that the multiple evaluations of a ENCODE or DECODE function within a single statement caused the random generator to be reinitialized at each evaluation, even though the parameters were constants. The solution is to initialize the random generator only once if the password (seed) parameter is constant. @ mysql-test/r/func_str.result Add test case result. @ mysql-test/r/ps.result Add test case result. @ mysql-test/t/func_str.test Add test case for Bug#49141 @ mysql-test/t/ps.test Add test case for Bug#49141 @ sql/item_strfunc.cc Move seed generation code to a separate method. Seed only once if the password (seed) argument is constant. Remove duplicated code and use a transform method to apply encoding or decoding. @ sql/item_strfunc.h Add parameter to signal whether the PRNG is already seeded. Introduce transform method. Combine val_str methods. @ sql/sql_crypt.cc Remove method. @ sql/sql_crypt.h Seed is supplied as two long integers.
[4 Dec 2009 15:11]
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/92898 3245 Davi Arnaut 2009-12-04 Bug#49141: Encode function is significantly slower in 5.1 compared to 5.0 The problem was that the multiple evaluations of a ENCODE or DECODE function within a single statement caused the random generator to be reinitialized at each evaluation, even though the parameters were constants. The solution is to initialize the random generator only once if the password (seed) parameter is constant. This patch borrows code and ideas from Georgi Kodinov's patch. @ mysql-test/r/func_str.result Add test case result. @ mysql-test/r/ps.result Add test case result. @ mysql-test/t/func_str.test Add test case for Bug#49141 @ mysql-test/t/ps.test Add test case for Bug#49141 @ sql/item_strfunc.cc Move seed generation code to a separate method. Seed only once if the password (seed) argument is constant. Remove duplicated code and use a transform method to apply encoding or decoding. @ sql/item_strfunc.h Add parameter to signal whether the PRNG is already seeded. Introduce transform method. Combine val_str methods. @ sql/sql_crypt.cc Remove method. @ sql/sql_crypt.h Seed is supplied as two long integers.
[4 Dec 2009 15:37]
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/92904 3245 Davi Arnaut 2009-12-04 Bug#49141: Encode function is significantly slower in 5.1 compared to 5.0 The problem was that the multiple evaluations of a ENCODE or DECODE function within a single statement caused the random generator to be reinitialized at each evaluation, even though the parameters were constants. The solution is to initialize the random generator only once if the password (seed) parameter is constant. This patch borrows code and ideas from Georgi Kodinov's patch. @ mysql-test/r/func_str.result Add test case result. @ mysql-test/r/ps.result Add test case result. @ mysql-test/t/func_str.test Add test case for Bug#49141 @ mysql-test/t/ps.test Add test case for Bug#49141 @ sql/item_strfunc.cc Move seed generation code to a separate method. Seed only once if the password (seed) argument is constant. Remove duplicated code and use a transform method to apply encoding or decoding. @ sql/item_strfunc.h Add parameter to signal whether the PRNG is already seeded. Introduce transform method. Combine val_str methods. @ sql/sql_crypt.cc Remove method. @ sql/sql_crypt.h Seed is supplied as two long integers.
[4 Dec 2009 16:43]
Davi Arnaut
Queued to mysql-5.1-bugteam
[19 Dec 2009 8:30]
Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091219082307-f3i4fn0tm8trb3c0) (version source revid:alik@sun.com-20091216180721-eoa754i79j4ssd3m) (merge vers: 6.0.14-alpha) (pib:15)
[19 Dec 2009 8:33]
Bugs System
Pushed into 5.5.1-m2 (revid:alik@sun.com-20091219082021-f34nq4jytwamozz0) (version source revid:alexey.kopytov@sun.com-20091211164058-ycpe0f20d1c4h1gl) (merge vers: 5.5.0-beta) (pib:15)
[19 Dec 2009 8:37]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20091219082213-nhjjgmphote4ntxj) (version source revid:alik@sun.com-20091216180221-a5ps59gajad3pip9) (pib:15)
[8 Jan 2010 17:20]
Paul DuBois
Noted in 5.5.1, 6.0.14 changelogs. Execution of DECODE() and ENCODE() could be inefficient because multiple executions within a single statement reinitialized the random generator multiple times even with constant parameters. Setting report to NDI pending push to 5.1.x, Celosia.
[15 Jan 2010 9:02]
Bugs System
Pushed into 5.1.43 (revid:joro@sun.com-20100115085139-qkh0i0fpohd9u9p5) (version source revid:davi.arnaut@sun.com-20091204153658-09w7l2edgszt8qe7) (merge vers: 5.1.42) (pib:16)
[15 Jan 2010 18:48]
Paul DuBois
Noted in 5.1.43 changelog. Setting report to NDI pending push to Celosia.
[12 Mar 2010 14:13]
Bugs System
Pushed into 5.1.44-ndb-7.0.14 (revid:jonas@mysql.com-20100312135944-t0z8s1da2orvl66x) (version source revid:jonas@mysql.com-20100312115609-woou0te4a6s4ae9y) (merge vers: 5.1.44-ndb-7.0.14) (pib:16)
[12 Mar 2010 14:29]
Bugs System
Pushed into 5.1.44-ndb-6.2.19 (revid:jonas@mysql.com-20100312134846-tuqhd9w3tv4xgl3d) (version source revid:jonas@mysql.com-20100312060623-mx6407w2vx76h3by) (merge vers: 5.1.44-ndb-6.2.19) (pib:16)
[12 Mar 2010 14:44]
Bugs System
Pushed into 5.1.44-ndb-6.3.33 (revid:jonas@mysql.com-20100312135724-xcw8vw2lu3mijrhn) (version source revid:jonas@mysql.com-20100312103652-snkltsd197l7q2yg) (merge vers: 5.1.44-ndb-6.3.33) (pib:16)
[12 Mar 2010 16:42]
Paul DuBois
Fixed in earlier 5.1.x, 5.5.x.
Description: Encode function is significantly slower in 5.1 compared to 5.0 How to repeat: select benchmark(1000000, encode('hello','goodbye')); 4.1.24 - 0.54 s 5.0.58 - 0.57 s 5.0.87 - 0.59 s 5.1.28 - ~20 s 5.1.38 - ~23 s Suggested fix: Approximately same performance is expected.