MySQL Bugs: #107107: Redundant "Reset stmt" when setting useServerPrepStmts&cachePrepStmts to true

Bug #107107	Redundant "Reset stmt" when setting useServerPrepStmts&cachePrepStmts to true
Submitted:	23 Apr 2022 4:00	Modified:	9 Jan 18:48
Reporter:	Yuankai Xue	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Connector / J	Severity:	S2 (Serious)
Version:	8.0.28, 8.0.33	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	Contribution, prepared statement caches

Description:
When setting both useServerPrepStmts and cachePrepStmts to true, my general log looks like:
7 Prepare select * from test where id=?
7 Execute select * from test where id=1
7 Reset stmt
7 Execute select * from test where id=2
7 Reset stmt
7 Execute select * from test where id=3

It seems like the prepared statement cache does take effect but there're unexpected "Reset stmt" which cause extra round-trips.

My original question can be found here which contains more details like related source code.
https://forums.mysql.com/read.php?39,704080,704080#msg-704080

How to repeat:
I'm using MySQL Connector/J (both version 8.0.28 and 8.0.13 have been tested) as the driver on client side. Following is part of my code for test purpose:
PreparedStatement ps = null;
String url = "jdbc:mysql://10.86.49.16:3306/test?useServerPrepStmts=true&cachePrepStmts=true";
...
Class.forName("com.mysql.jdbc.Driver");
conn = DriverManager.getConnection(url, user, password);
String sql = "select * from test where id=?";
for (int i = 1; i <= 3; i++) {
ps = conn.prepareStatement(sql);
ps.setInt(1, i);
ps.execute();
ps.close();
}

When setting "useServerPrepStmts=true" alone, my general log looks like this:
6 Prepare select * from test where id=?
6 Execute select * from test where id=1
6 Close stmt
6 Prepare select * from test where id=?
6 Execute select * from test where id=2
6 Close stmt
6 Prepare select * from test where id=?
6 Execute select * from test where id=3
6 Close stmt

However after enabling "cachePrepStmts" together, the log becomes:
7 Prepare select * from test where id=?
7 Execute select * from test where id=1
7 Reset stmt
7 Execute select * from test where id=2
7 Reset stmt
7 Execute select * from test where id=3

Suggested fix:
I've checked the following code pieces in github and seems like the logic has been changed five years ago. In my case, when closing the prepared statement, the clearServerParameters=true and hadLongData=false which results in this.queryBindings.setLongParameterSwitchDetected(true). I think it should be set to false instead of true in this case.

com.mysql.cj.ServerPreparedQuery#clearParameters

/**
 * @param clearServerParameters
 *            flag indicating whether we need an additional clean up
 */
public void clearParameters(boolean clearServerParameters) {
    boolean hadLongData = false;
    if (this.queryBindings != null) {
        hadLongData = this.queryBindings.clearBindValues();
        this.queryBindings.setLongParameterSwitchDetected(clearServerParameters && hadLongData ? false : true);
    }
    ...
}

Hello Yuankai Xue,

Thank you for the report and test case.
Verified as described.

regards,
Umesh

The suggested fix is verified to work perfectly; This fix is, replacing line src/main/core-impl/java/com/mysql/cj/ServerPreparedQuery.java Line 560 (https://github.com/mysql/mysql-connector-j/blob/7d6b0800528b6b25c68b52dc10d6c1c8429c100c/s...) 

From
            this.queryBindings.setLongParameterSwitchDetected(clearServerParameters && hadLongData ? false : true);
to
            this.queryBindings.setLongParameterSwitchDetected(clearServerParameters && hadLongData ? true : false);

Here's simple test case:
========================

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.sql.DatabaseMetaData;
import java.util.Date;

public class PreparedStmtTest {
  private Connection connect = null;
  private Statement statement = null;
  private PreparedStatement ps = null;
  private ResultSet resultSet = null;

  public void doit() {
    try {
      Class.forName("com.mysql.cj.jdbc.Driver");
      connect = DriverManager.getConnection("jdbc:mysql://127.0.0.1:8032/test?user=msandbox&password=msandbox&useServerPrepStmts=true&cachePrepStmts=true");
      DatabaseMetaData meta = connect.getMetaData();
      System.out.println(meta.getDriverVersion());
      System.out.println(meta.getDatabaseProductVersion());
      statement = connect.createStatement();
      resultSet = statement.executeQuery("select 1 as col1");
      resultSet.next();
      System.out.println("Hello World! " + resultSet.getString("col1"));

      String my_sql = "/* prepared on each iteration */ select * from test.joinit where i=?";
      for (int i = 1; i <= 3; i++) {
        System.out.println("for-loop iteration #" + i);
        ps = connect.prepareStatement(my_sql);
        ps.setInt(1, i);
        ps.execute();
        ps.close();
      }

    } catch (SQLException ex) {
      System.out.println("SQLException: " + ex.getMessage());
      System.out.println("SQLState: " + ex.getSQLState());
      System.out.println("VendorError: " + ex.getErrorCode());
    } catch (Exception e) {
      System.out.println("Exception: " + e.toString());
    }
    try {
    if (resultSet != null) {
      resultSet.close();
    }
    if (statement != null) {
      statement.close();
    }
    if (connect != null) {
      connect.close();
    }
    } catch (Exception ex) {
      System.out.println("Exception while cleaning up resources: " + ex.toString());
    }
  }
  public static void main(String[] argsa) {
    System.out.println("Starting...");
    PreparedStmtTest x = new PreparedStmtTest();
    System.out.println("x: " + x.toString());
    x.doit();
    System.out.println("Done...");
  }
}

And here are sample outputs with and without suggested fix:
No fix:
=======
2023-05-03T22:08:48.175018Z        11 Prepare   /* prepared on each iteration */ select * from test.joinit where i=?
2023-05-03T22:08:48.179220Z        11 Execute   /* prepared on each iteration */ select * from test.joinit where i=1
2023-05-03T22:08:48.181477Z        11 Reset stmt
2023-05-03T22:08:48.181647Z        11 Execute   /* prepared on each iteration */ select * from test.joinit where i=2
2023-05-03T22:08:48.182158Z        11 Reset stmt
2023-05-03T22:08:48.182289Z        11 Execute   /* prepared on each iteration */ select * from test.joinit where i=3

Fixed:
=======
2023-05-11T17:13:55.558672Z    57 Query select 1 as col1
2023-05-11T17:13:55.583521Z    57 Prepare /* prepared on each iteration */ select * from test.joinit where i=?
2023-05-11T17:13:55.589895Z    57 Execute /* prepared on each iteration */ select * from test.joinit where i=1
2023-05-11T17:13:55.593048Z    57 Execute /* prepared on each iteration */ select * from test.joinit where i=2
2023-05-11T17:13:55.594643Z    57 Execute /* prepared on each iteration */ select * from test.joinit where i=3
2023-05-11T17:13:55.595655Z    57 Quit

New code also reacts correctly to the setInt to setBlob replacement:
        FileInputStream inputStream= new FileInputStream("param.txt");
        ps.setBlob(1, inputStream);

Fixed with streams:
===================
2023-05-11T17:30:47.338186Z    59 Prepare /* prepared on each iteration */ select * from test.joinit where i=?
2023-05-11T17:30:47.342712Z    59 Long Data 
2023-05-11T17:30:47.344936Z    59 Execute /* prepared on each iteration */ select * from test.joinit where i='1\n'
2023-05-11T17:30:47.348442Z    59 Reset stmt

This bug has been open for over 1 year, and given it impacts performance in a noticeable way and has such an easy fix, would be nice to have an idea of when it could be expected to be fixed.

Hi Marcos Albe,

Thanks for the info! Our team is suffering from this bug and has to go without server prepared statement cache.
May I know if you can help escalate to the team and give a rough idea when it will be released?

Many thanks,
Yuankai Xue

Contribution submitted via Github - Fix https://bugs.mysql.com/bug.php?id=107107 (*) Contribution by Marcos Albe (Github markusalbe, mysql-connector-j/pull/97#issuecomment-1567453628): > Hi, thank you for your contribution. Please confirm this code is submitted under the terms of the OCA (Oracle''s Contribution Agreement) you have previously signed by cutting and pasting the following text as a comment: "I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it." Thanks I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: git_patch_1352736171.txt (text/plain), 1.23 KiB.

Basic test of multiple scenarios where a reset is [not] needed

Attachment: PreparedStmtTest.java (application/octet-stream, text), 8.38 KiB.

Prevoius patch we suggested did not covered some scenarios; This one should cover all of them.

Attachment: bug107107-contrib.patch (application/octet-stream, text), 1.16 KiB.

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Attachment: bug107107-contrib.patch (application/octet-stream, text), 1.16 KiB.

Posted by developer:
 
Added the following entry to the Connector/J 8.3.0 changelog: 

"When the connection properties useServerPrepStmts and cachePrepStmts were both set to true, the PreparedStatement was reset every time after an execution, causing performance issues. With this fix, unnecessary resets are avoided. Thanks to Marcos Albe for contributing to this fix."