MySQL Bugs: #2050: 10 to 1 performance drop with server 4.1.1

Bug #2050	10 to 1 performance drop with server 4.1.1
Submitted:	8 Dec 2003 17:07	Modified:	9 Jul 2004 22:54
Reporter:	Quartz12h
Status:	Closed
Category:	Server	Severity:	S2 (Serious)
Version:	4.1.1alpha	OS:	Microsoft Windows (w2k)
Assigned to:	Dmitri Lenev	Target Version:

Description:
long server-side "update" prepared statements (200 fields of 20 chars per name each) are
10 times faster with 4.1.0.

Just installed the 4.1.1 alpha server and it performs as bad as simple statements or
client-side prepared statements.

Using connector/J
mysql-connector-java-3.1-nightly-20031205-bin.jar

Hypothesis: either it ignores my index, or it does not perform server side prepared
statement.

How to repeat:
package stress;

import java.io.File;
import java.net.URL;
import java.net.URLClassLoader;
import java.sql.*;
import java.util.Properties;

public class TestSQLStatements {

	//------- populator for table "stress.Data" ---------------

	static final String createtbl_prefix = "CREATE TABLE data (\n" + "  id int(11) NOT NULL
default '0',\n" + "  t int(11) NOT NULL default '0',\n";

	static final String fielddef = " int(11) NOT NULL default '0',\n";
	static final String createtbl_suffix = " PRIMARY KEY (id,t)\n" + ") TYPE=MyISAM;";

	public static void main(String[] args) throws Exception {
		System.out.println("[nf [nid [ntests]]]");

		int NF = Integer.parseInt(args.length >= 1 ? args[0] : "200"); //different fields
		int N_ID = Integer.parseInt(args.length >= 1 ? args[1] : "50"); //different ids
		int NTBB = Integer.parseInt(args.length >= 2 ? args[3] : "10"); //tests for each id, per
batch
		int NB = Integer.parseInt(args.length >= 4 ? args[4] : "5"); //batches
		int NUMTESTS = NB * NTBB;

		Connection conn = null;
		try {
			//String path = "c:/temp/mysql-connector-java-3.0.8-stable-bin.jar";
			//String path = "c:/temp/mysql-connector-java-3.0.9-stable-bin.jar";
			//String path = "C:\\java\\eclipse_prj\\mysql_connJ\\output";
			String path = "c:/temp/mysql-connector-java-3.1-nightly-20031205-bin.jar";
			
			String user = "root";
			String pwd = "x";
			String url = "jdbc:mysql://127.0.0.1:3306/stress";

			Properties props = new Properties();
			props.setProperty("useServerPrepStmts", "true");

			//------------------

			File f = new File(path.replace('/', File.separatorChar));
			System.out.println(f + " : " + f.exists());
			URL u = f.toURL();
			System.out.println("url : " + u);

			URLClassLoader uc = new URLClassLoader(new URL[] { u });
			Driver d = (Driver)uc.loadClass("com.mysql.jdbc.Driver").newInstance();

			props.setProperty("user", user);
			if (pwd != null)
				props.setProperty("password", pwd);
			conn = d.connect(url, props);
			
			//-------------------------------
			
			prepareDB(conn, NF);
			
			//testGetMetadataAndClose(conn);

			workIt(conn, NF, N_ID, NUMTESTS);
			
			workItBatch(conn, NF, N_ID, NTBB, NB);
			
			//-------------------------------
		} catch (Exception e) {
			e.printStackTrace();
		} finally {
			if (conn != null) {
				try {
					conn.close();
				} catch (Exception e) {
				}
			}
		}
	}

	static void prepareDB(Connection conn, int nfields) throws Exception {
		Statement st = conn.createStatement();

		try {
			st.execute("drop table Data");
		} catch (Exception e) {
			System.out.println(e);
		}

		try {
			StringBuffer sb = new StringBuffer(createtbl_prefix);
			for (int i = 1; i <= nfields; i++) {
				sb.append("  field_").append(i).append("_abcdefghij").append(fielddef);
			}
			sb.append(createtbl_suffix);
			String sql = sb.toString();
			System.out.println(sql);
			st.execute(sql);
		} catch (Exception e) {
			System.out.println(e);
		}

	}

	static void testGetMetadataAndClose(Connection conn) throws Exception {
		long t1 = 0;
		long t2 = 0;
		int N = 1000000;

		for (int i = 1; i <= N; i++) {
			conn.getMetaData();
		}
		t1 = System.currentTimeMillis();
		for (int i = 1; i <= N; i++) {
			conn.getMetaData();
		}
		t2 = System.currentTimeMillis();
		System.out.println("getMetaData avg: " + 1000.0 * (t2 - t1) / N);

		for (int i = 1; i <= N; i++) {
			conn.isClosed();
		}
		t1 = System.currentTimeMillis();
		for (int i = 1; i <= N; i++) {
			conn.isClosed();
		}
		t2 = System.currentTimeMillis();
		System.out.println("isClosed avg: " + 1000.0 * (t2 - t1) / N);
	}

	static void workIt(Connection conn, int NF, int N_ID, int NUMTESTS) throws Exception {

		StringBuffer insertStart = new StringBuffer("INSERT INTO Data (id,t,");
		StringBuffer prepInsert2 = new StringBuffer("?,?,");
		StringBuffer prepUpd1 = new StringBuffer("UPDATE Data SET ");
		for (int i = 1; i <= NF; i++) {
			insertStart.append("field_").append(i).append("_abcdefghij");
			prepInsert2.append('?');
			prepUpd1.append("field_").append(i).append("_abcdefghij=?");
			if (i < NF) {
				insertStart.append(',');
				prepInsert2.append(',');
				prepUpd1.append(',');
			}
		}
		insertStart.append(") VALUES (");

		StringBuffer fullPrepInsert = new
StringBuffer(insertStart.toString()).append(prepInsert2).append(')');
		System.out.println(fullPrepInsert.toString());

		StringBuffer fullPrepUpd = new StringBuffer(prepUpd1.toString()).append(" WHERE (id=?
AND t=?)");
		System.out.println(fullPrepUpd.toString());

		PreparedStatement pst_i = conn.prepareStatement(fullPrepInsert.toString()); //"insert
into Data (id, t, f1, f2, f3, f4, f5) values(?,?,?,?,?,?,?)");
		PreparedStatement pst_u = conn.prepareStatement(fullPrepUpd.toString()); //"update Data
set f1=?, f2=?, f3=?, f4=?, f5=? where (id=? AND t=?)");
		Statement st = conn.createStatement();

		//---------

		int N = N_ID * NUMTESTS;
		StringBuffer sql_i = new StringBuffer(insertStart.toString());
		int mark = sql_i.length();

		StringBuffer sql_u = new StringBuffer();
		long t1 = 0;
		long t2 = 0;

		int ans = st.executeUpdate("delete from Data");
		System.out.println("Delete: " + ans);
		System.out.print("Waiting, 5");
		Thread.sleep(1000); System.out.print(", 4");
		Thread.sleep(1000); System.out.print(", 3");
		Thread.sleep(1000); System.out.print(", 2");
		Thread.sleep(1000); System.out.print(", 1");
		Thread.sleep(1000); System.out.println(" go!");

		//-----

		t1 = System.currentTimeMillis();
		for (int id = 1; id <= N_ID; id++) {
			System.out.print(".");
			for (int i = 1; i <= NUMTESTS; i++) {
				int t = i * 1000;

				//st
				sql_i.setLength(mark);
				sql_i.append(id).append(',');
				sql_i.append(t).append(',');
				for (int k = 1; k <= NF; k++) {
					sql_i.append(k);
					if (k < NF)
						sql_i.append(',');
				}
				sql_i.append(')');
				insertByStatement(st, sql_i.toString());
			}
		}
		t2 = System.currentTimeMillis();
		System.out.println("st insert avg: " + 1000.0 * (t2 - t1) / N);

		t1 = System.currentTimeMillis();
		for (int id = 1; id <= N_ID; id++) {
			System.out.print(".");
			for (int i = 1; i <= NUMTESTS; i++) {
				int t = i * 1000;

				sql_u.setLength(0);

				sql_u.append("UPDATE Data SET ");
				for (int k = 1; k <= NF; k++) {
					sql_u.append("field_").append(k).append("_abcdefghij=").append(-k);
					if (k < NF)
						sql_u.append(',');
				}
				sql_u.append(" WHERE (id=").append(id);
				sql_u.append(" AND t=").append(t);
				sql_u.append(')');
				updateByStatement(st, sql_u.toString());
			}
		}
		t2 = System.currentTimeMillis();
		System.out.println("st update avg: " + 1000.0 * (t2 - t1) / N);

		//-----

		t1 = System.currentTimeMillis();
		for (int id = 1; id <= N_ID; id++) {
			System.out.print(".");
			for (int i = 1; i <= NUMTESTS; i++) {
				int t = i * 1000;

				//ps
				pst_i.setInt(1, -id);
				pst_i.setInt(2, t);
				for (int k = 1; k <= NF; k++)
					pst_i.setInt(2 + k, k);
				insertByPreparedStatement(pst_i);
			}
		}
		t2 = System.currentTimeMillis();
		System.out.println("pst insert avg: " + 1000.0 * (t2 - t1) / N);

		t1 = System.currentTimeMillis();
		for (int id = 1; id <= N_ID; id++) {
			System.out.print(".");
			for (int i = 1; i <= NUMTESTS; i++) {
				int t = i * 1000;

				for (int k = 1; k <= NF; k++)
					pst_u.setInt(k, -k);

				pst_u.setInt(NF + 1, -id);
				pst_u.setInt(NF + 2, t);
				updateByPreparedStatement(pst_u);
			}
		}
		t2 = System.currentTimeMillis();
		System.out.println("pst update avg: " + 1000.0 * (t2 - t1) / N);

		System.out.println("done!");

	}
	
	
	//==== isolated methods, for optimizeit tracking only =====
	
	static int insertByStatement(Statement st, String sql) throws Exception {
		return st.executeUpdate(sql.toString());
	}

	static int insertByPreparedStatement(PreparedStatement pst) throws Exception {
		return pst.executeUpdate();
	}

	static int updateByStatement(Statement st, String sql) throws Exception {
		return st.executeUpdate(sql.toString());
	}

	static int updateByPreparedStatement(PreparedStatement pst) throws Exception {
		return pst.executeUpdate();
	}

	//--------------------------

	static void workItBatch(Connection conn, int NF, int N_ID, int NB, int NTBB) throws
Exception {

		StringBuffer insertStart = new StringBuffer("INSERT INTO Data (id,t,");
		StringBuffer prepInsert2 = new StringBuffer("?,?,");
		StringBuffer prepUpd1 = new StringBuffer("UPDATE Data SET ");
		for (int i = 1; i <= NF; i++) {
			insertStart.append("field_").append(i).append("_abcdefghij");
			prepInsert2.append('?');
			prepUpd1.append("field_").append(i).append("_abcdefghij=?");
			if (i < NF) {
				insertStart.append(',');
				prepInsert2.append(',');
				prepUpd1.append(',');
			}
		}
		insertStart.append(") VALUES (");

		StringBuffer fullPrepInsert = new
StringBuffer(insertStart.toString()).append(prepInsert2).append(')');
		System.out.println(fullPrepInsert.toString());

		StringBuffer fullPrepUpd = new StringBuffer(prepUpd1.toString()).append(" WHERE (id=?
AND t=?)");
		System.out.println(fullPrepUpd.toString());

		PreparedStatement pst_i = conn.prepareStatement(fullPrepInsert.toString()); //"insert
into Data (id, t, f1, f2, f3, f4, f5) values(?,?,?,?,?,?,?)");
		PreparedStatement pst_u = conn.prepareStatement(fullPrepUpd.toString()); //"update Data
set f1=?, f2=?, f3=?, f4=?, f5=? where (id=? AND t=?)");
		Statement st = conn.createStatement();

		//---------

		int N = N_ID * NB * NTBB;
		StringBuffer sql_i = new StringBuffer(insertStart.toString());
		int mark = sql_i.length();

		StringBuffer sql_u = new StringBuffer();
		long t1 = 0;
		long t2 = 0;

		int ans = st.executeUpdate("delete from Data");
		System.out.println("Delete: " + ans);
		System.out.print("Waiting, 5");
		Thread.sleep(1000); System.out.print(", 4");
		Thread.sleep(1000); System.out.print(", 3");
		Thread.sleep(1000); System.out.print(", 2");
		Thread.sleep(1000); System.out.print(", 1");
		Thread.sleep(1000); System.out.println(" go!");
		
		
		conn.setAutoCommit(false);
		
		//-----
		
		
		t1 = System.currentTimeMillis();
		for (int id = 1; id <= N_ID; id++) {
			System.out.print(".");
			for (int b = 1; b <= NB; b++) {
				for (int i = 1; i <= NTBB; i++) {
					int t = (b * NTBB + i) * 1000;

					//st
					sql_i.setLength(mark);
					sql_i.append(id).append(',');
					sql_i.append(t).append(',');
					for (int k = 1; k <= NF; k++) {
						sql_i.append(k);
						if (k < NF)
							sql_i.append(',');
					}
					sql_i.append(')');

					st.addBatch(sql_i.toString());
				}

				st.executeBatch();
				conn.commit();
			}
		}
		t2 = System.currentTimeMillis();
		System.out.println("st batch insert avg: " + 1000.0 * (t2 - t1) / N);

		t1 = System.currentTimeMillis();
		for (int id = 1; id <= N_ID; id++) {
			System.out.print(".");
			for (int b = 1; b <= NB; b++) {
				for (int i = 1; i <= NTBB; i++) {
					int t = (b * NTBB + i) * 1000;

					sql_u.setLength(0);

					sql_u.append("UPDATE Data SET ");
					for (int k = 1; k <= NF; k++) {
						sql_u.append("field_").append(k).append("_abcdefghij=").append(-k);
						if (k < NF)
							sql_u.append(',');
					}
					sql_u.append(" WHERE (id=").append(id);
					sql_u.append(" AND t=").append(t);
					sql_u.append(')');

					st.addBatch(sql_u.toString());
				}

				st.executeBatch();
				conn.commit();
			}
		}
		t2 = System.currentTimeMillis();
		System.out.println("st batch update avg: " + 1000.0 * (t2 - t1) / N);

		//-----

		t1 = System.currentTimeMillis();
		for (int id = 1; id <= N_ID; id++) {
			System.out.print(".");
			for (int b = 1; b <= NB; b++) {
				for (int i = 1; i <= NTBB; i++) {
					int t = (b * NTBB + i) * 1000;

					//ps
					pst_i.setInt(1, -id);
					pst_i.setInt(2, t);
					for (int k = 1; k <= NF; k++)
						pst_i.setInt(2 + k, k);

					pst_i.addBatch();
				}

				pst_i.executeBatch();
				conn.commit();
			}
		}
		t2 = System.currentTimeMillis();
		System.out.println("pst batch insert avg: " + 1000.0 * (t2 - t1) / N);

		t1 = System.currentTimeMillis();
		for (int id = 1; id <= N_ID; id++) {
			System.out.print(".");
			for (int b = 1; b <= NB; b++) {
				for (int i = 1; i <= NTBB; i++) {
					int t = (b * NTBB + i) * 1000;

					for (int k = 1; k <= NF; k++)
						pst_u.setInt(k, -k);

					pst_u.setInt(NF + 1, -id);
					pst_u.setInt(NF + 2, t);

					pst_u.addBatch();
				}

				pst_u.executeBatch();
				conn.commit();
			}
		}
		t2 = System.currentTimeMillis();
		System.out.println("pst batch update avg: " + 1000.0 * (t2 - t1) / N);
		
		
		//-------
		
		conn.setAutoCommit(true);
		
		System.out.println("done!");

	}

}

Verified against 4.1.2/Linux.

Inserts are slightly faster, but updates are dramatically slower.  The number of columns
did not have any relevance in my tests; updates were 10-30 times slower regardless.

Per the query log, the statements are using server-side prepared statements.  For whatever
it may be worth for debugging, Connector/J 3.0 (without server-side prepstmt of course)
did not demonstrate such drastic performance degradation against 4.1.2.

Thank you.

As testing Connector/J 3.1 against 4.1.0 and 4.1.2 shows the performance degradation, I am
removing Mark's assignment since this would appear to be something in the server rather
than in Connector/J itself.

With a C++ test basically doing the same thing, I cannot repeat the performance loss,
unless I, in another connection, select something from the table while the prepared
statement UPDATE is processing (single row select against primary key; returns
immediately).

For whatever reason, this causes the update to slow to a crawl, although it does
eventually complete.  CPU usage stays high throughout.  Thread stays in "Updating" state
when this occurs.

This, however, occurs with 4.1.0 also, so I don't know if it is the same issue.

how is that one going?

Hi, thank you for pointing to this bug!

I was able to repeat perfomance degradation from 4.1.0 to 4.1.1 (only updates degrade) and
4.1.2 (both inserts and updates degraded). I even don't have to run select in concurrent
thread (so may be Dean spotted other bug).

This degradation is consequence of fixing bug in prepared statement handling 
code that could easily lead to server crashes.

Note for devs: We didn't executed Item_field::fix_fields() twice before 4.1.2,
and then we have introduced cleanup() method and fix_fields() started to execute for each
prep stmt invocation, perfomance degradation followed. This is because
fix_fields() for insert and updates to user's table with 200 fields take about
90% of query execution time (probably due to very bad hash distribution for 
his case (I've observed a lot of relatively long conflict resolution lists in hash in this
case)), for table with 5 fields it consumes about 10% of query execution time.

For soothing this problem small optimization is proposed, but much better and efficient
fix for this could be implemented when new .frm format and new table definition cache will
be introduced (and this will probably happen in 5.0).

ChangeSet
  1.1720 04/03/28 04:11:54 dlenev@brandersnatch.localdomain +8 -0
  "Fix" for BUG #2050 "10 to 1 performance drop with server 4.1.1".

Thank you for your bug report. This issue has been committed to our
source repository of that product and will be incorporated into the
next release.

If necessary, you can access the source repository and build the latest
available version, including the bugfix, yourself. More information 
about accessing the source trees is available at
    http://www.mysql.com/doc/en/Installing_source_tree.html

Additional info:

ChangeSet 1.1755 2004/03/31 22:17:10 dlenev@brandersnatch.localdomain
  Merge of fix for bug #2050 and bug #3307

Performance drop of prepared statements still there: but 2-to-1 approx.

srv 4.1.3a

connector/j  3.1.3b
..................................................st insert avg: 5612.4
..................................................st update avg: 6317.2
..................................................pst insert avg: 1506.0
..................................................pst update avg: 1514.4

srv 4.1.0
connector/j 3.1.1a
..................................................st insert avg: 5095.6
..................................................st update avg: 5359.6
..................................................pst insert avg: 725.2
..................................................pst update avg: 749.2

(note that connector/j 3.1.1a doesn't work with srv 4.1.3b, some charset exception)

Hi!

This degradation exists only becuase there was a serious bug in 4.1.1, so some piece of
code was faster but was buggy. Unfortunately there were no way to fix this bug in 4.1
without loosing some speed.
 
Some changes that are planned for 5.0 should allow us to improve speed of prepared
statements so we can move one step further to perfomance that you have observed in 4.1.1.
But we can't do much in 4.1.