Bug #2050 10 to 1 performance drop with server 4.1.1
Submitted: 8 Dec 2003 16:07 Modified: 9 Jul 2004 20:54
Reporter: Quartz 12h Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:4.1.1alpha OS:Windows (w2k)
Assigned to: Dmitry Lenev CPU Architecture:Any

[8 Dec 2003 16:07] Quartz 12h
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!");

	}

}
[16 Dec 2003 12:00] Dean Ellis
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.
[16 Dec 2003 16:12] Dean Ellis
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.
[16 Dec 2003 17:56] Dean Ellis
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.
[3 Feb 2004 6:29] Quartz 12h
how is that one going?
[27 Mar 2004 15:37] Dmitry Lenev
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).
[27 Mar 2004 16:14] Dmitry Lenev
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".
[31 Mar 2004 10:30] Dmitry Lenev
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
[9 Jul 2004 16:54] Quartz 12h
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)
[9 Jul 2004 20:54] Dmitry Lenev
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.