Bug #85933 Performance regression with Prepared Statements
Submitted: 13 Apr 2017 13:25 Modified: 27 Sep 2017 1:33
Reporter: Andrey Hristov Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Prepared statements Severity:S5 (Performance)
Version:8.0.1-dmr OS:Any
Assigned to: CPU Architecture:Any
Tags: regression

[13 Apr 2017 13:25] Andrey Hristov
Description:
In 8.0.1 the PS subsystem has been refactored. After running the PHP test suite with the new MySQL version one tests timed out - the test testing the limits of prepared statements.
The very same tests doesn't time out with MySQL 5.7.18.
I decided to run the test in  manual mode to give it more time and see how much time it takes to run if there are no time limits.

With MySQL 5.7.18:
andrey@poohie:/work/dev/php/php-7.1$ time ./php ext/mysqli/tests/mysqli_stmt_bind_limits.php
Testing 273 columns with 240 rows...
... table created
... statement with 65520 parameters prepared
Statement done
bool(true)
Testing 273 columns with 240 rows...
... table created
... statement with 65520 parameters prepared
Statement done
bool(true)
done!
real    0m22.776s
user    0m15.123s
sys     0m6.650s
------------------------

With MySQL 8.0.1-dmr:
andrey@poohie:/work/dev/php/php-7.1$ time ./php ext/mysqli/tests/mysqli_stmt_bind_limits.php
Testing 273 columns with 240 rows...
... table created
... statement with 65520 parameters prepared
Statement done
bool(true)
Testing 273 columns with 240 rows...
... table created
... statement with 65520 parameters prepared
Statement done
bool(true)
done!
real    2m34.143s
user    0m15.110s
sys     0m6.612s
----------------------
As you can see, the user and sys are very similar, as they are related to PHP. The "real" is the wall clock time. It went from 23s to 154 seconds. Almost 7-fold deterioration. 

I decided to execute SHOW FULL PROCESSLIST while the test was running with 8.0.1 . To my surprise the server was hanging while preparing the insert query which has 270 rows to be prepare and 240 columns. Two such queries are prepared. I took about 75s per query to prepare. Here is the output:
mysql> show full processlist\G
*************************** 1. row ***************************
     Id: 5
   User: root
   Host: localhost
     db: NULL
Command: Query
   Time: 0
  State: starting
   Info: show full processlist
*************************** 2. row ***************************
     Id: 9
   User: root
   Host: localhost:42179
     db: test
Command: Prepare
   Time: 75
  State: starting
   Info: INSERT INTO test(col0, col1, col2, col3, col4, col5, col6, col7, col8, col9, col10, col11, col12, col13, col14, col15, col16, col17, col18, col19, col20, col21, col22, col23, col24, col25, col26, col27, col28, col29, col30, col31, col32, col33, col34, col35, col36, col37, col38, col39, col40, col41, col42, col43, col44, col45, col46, col47, col48, col49, col50, col51, col52, col53, col54, col55, col56, col57, col58, col59, col60, col61, col62, col63, col64, col65, col66, col67, col68, col69, col70, col71, col72, col73, col74, col75, col76, col77, col78, col79, col80, col81, col82, col83, col84, col85, col86, col87, col88, col89, col90, col91, col92, col93, col94, col95, col96, col97, col98, col99, col100, col101, col102, col103, col104, col105, col106, col107, col108, col109, col110, col111, col112, col113, col114, col115, col116, col117, col118, col119, col120, col121, col122, col123, col124, col125, col126, col127, col128, col129, col130, col131, col132, col133, col134, col135, col136, col137, col138, col139, col140, col141, col142, col143, col144, col145, col146, col147, col148, col149, col150, col151, col152, col153, col154, col155, col156, col157, col158, col159, col160, col161, col162, col163, col164, col165, col166, col167, col168, col169, col170, col171, col172, col173, col174, col175, col176, col177, col178, col179, col180, col181, col182, col183, col184, col185, col186, col187, col188, col189, col190, col191, col192, col193, col194, col195, col196, col197, col198, col199, col200, col201, col202, col203, col204, col205, col206, col207, col208, col209, col210, col211, col212, col213, col214, col215, col216, col217, col218, col219, col220, col221, col222, col223, col224, col225, col226, col227, col228, col229, col230, col231, col232, col233, col234, col235, col236, col237, col238, col239, col240, col241, col242, col243, col244, col245, col246, col247, col248, col249, col250, col251, col252, col253, col254, col255, col256, col257, col258, col259, col260, col261, col262, col263, col264, col265, col266, col267, col268, col269, col270, col271, col272) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ........... , ?, ?, ?, ?)
2 rows in set (0,00 sec)

I have shortened the output a bit as it doesn't the fit the 8k limitation of the size of a report. The whole statement is 

How to repeat:
Use mysqli_stmt_bind_limits.phpt from the PHP test suite
[17 Apr 2017 11:46] Umesh Shastry
Hello Andrey Hristov,

Thank you for the report and feedback.
Verified as described.

###
8.0.2
-
real    0m32.905s
user    0m2.776s
sys     0m0.030s

5.7.18
-
real    0m3.094s
user    0m2.775s
sys     0m0.036s

Thanks,
Umesh
[17 Apr 2017 11:47] Umesh Shastry
test results

Attachment: 85933.results (application/octet-stream, text), 2.26 KiB.

[18 Apr 2017 13:11] Guilhem Bichot
Posted by developer:
 
for CTEs to work fine with PS I added a sort() of the list of PS parameters; for the test here which has thousands of parameters it slows things down.
Assigning to me.
[27 Sep 2017 1:33] Paul Dubois
Posted by developer:
 
Fixed in 8.0.3.

Prepared statements that used a common table expression and many ?
parameters could be slow.