| Bug #54086 | Server crashing when connector/J testsuite run against it | ||
|---|---|---|---|
| Submitted: | 29 May 2010 18:46 | Modified: | 23 Sep 2010 8:41 |
| Reporter: | Erica Moss | Email Updates: | |
| Status: | No Feedback | Impact on me: | |
| Category: | MySQL Server: General | Severity: | S1 (Critical) |
| Version: | mysql-5.5.3-m3-winx64 | OS: | Windows (server 2003 x64) |
| Assigned to: | Alexander Soklakov | CPU Architecture: | Any |
| Tags: | connector/J crash | ||
[29 May 2010 18:50]
Erica Moss
query log leading to crash
Attachment: query log (application/octet-stream, text), 349.32 KiB.
[30 May 2010 10:44]
MySQL Verification Team
Hi Eric! Please upload the mysql server error log so we might see crash related info. does drop table crash?
[31 May 2010 5:47]
Tonci Grgin
Eric, please do run StatementRegressionTest from Eclipse where you can choose test by test.
[3 Jun 2010 5:06]
MySQL Verification Team
i doubt this bug is verified sufficiently...
[18 Jun 2010 8:42]
Tonci Grgin
Eric, I suggest you to try outside VM (real box) as I can not repeat the crash... My guess would be that something in VM timed out. Now, we are all aware what all can go wrong here but still. Log from the test that fails for you: 100618 10:39:11 5 Connect root@localhost on test 5 Query /* mysql-connector-java-5.1.13 ( Revision: mark.matthews@oracle.com-20100615210030-3r8bsc9bv0efe6gv ) */SHOW VARIABLES WHERE Variable_name ='language' OR Variable_name = 'net_write_timeout' OR Variable_name = 'interactive_timeout' OR Variable_name = 'wait_timeout' OR Variable_name = 'character_set_client' OR Variable_name = 'character_set_connection' OR Variable_name = 'character_set' OR Variable_name = 'character_set_server' OR Variable_name = 'tx_isolation' OR Variable_name = 'transaction_isolation' OR Variable_name = 'character_set_results' OR Variable_name = 'timezone' OR Variable_name = 'time_zone' OR Variable_name = 'system_time_zone' OR Variable_name = 'lower_case_table_names' OR Variable_name = 'max_allowed_packet' OR Variable_name = 'net_buffer_length' OR Variable_name = 'sql_mode' OR Variable_name = 'query_cache_type' OR Variable_name = 'query_cache_size' OR Variable_name = 'init_connect' 5 Query /* mysql-connector-java-5.1.13 ( Revision: mark.matthews@oracle.com-20100615210030-3r8bsc9bv0efe6gv ) */SELECT @@session.auto_increment_increment 5 Query SHOW COLLATION 5 Query SET character_set_results = NULL 5 Query SET autocommit=1 5 Query SET sql_mode='STRICT_TRANS_TABLES' 5 Query SELECT VERSION() 5 Query DROP TABLE IF EXISTS t1 5 Query CREATE TABLE t1 (id INTEGER, x INTEGER) ENGINE = INNODB 5 Query DROP TABLE IF EXISTS t2 5 Query CREATE TABLE t2 (id INTEGER, x INTEGER) ENGINE = INNODB 5 Query INSERT INTO t1 VALUES (0, 0) 5 Query SET autocommit=0 5 Query SELECT * FROM t1 WHERE id=0 FOR UPDATE 6 Connect root@localhost on test 6 Query /* mysql-connector-java-5.1.13 ( Revision: mark.matthews@oracle.com-20100615210030-3r8bsc9bv0efe6gv ) */SHOW VARIABLES WHERE Variable_name ='language' OR Variable_name = 'net_write_timeout' OR Variable_name = 'interactive_timeout' OR Variable_name = 'wait_timeout' OR Variable_name = 'character_set_client' OR Variable_name = 'character_set_connection' OR Variable_name = 'character_set' OR Variable_name = 'character_set_server' OR Variable_name = 'tx_isolation' OR Variable_name = 'transaction_isolation' OR Variable_name = 'character_set_results' OR Variable_name = 'timezone' OR Variable_name = 'time_zone' OR Variable_name = 'system_time_zone' OR Variable_name = 'lower_case_table_names' OR Variable_name = 'max_allowed_packet' OR Variable_name = 'net_buffer_length' OR Variable_name = 'sql_mode' OR Variable_name = 'query_cache_type' OR Variable_name = 'query_cache_size' OR Variable_name = 'init_connect' 6 Query /* mysql-connector-java-5.1.13 ( Revision: mark.matthews@oracle.com-20100615210030-3r8bsc9bv0efe6gv ) */SELECT @@session.auto_increment_increment 6 Query SHOW COLLATION 6 Query SET character_set_results = NULL 6 Query SET autocommit=1 6 Query SET sql_mode='STRICT_TRANS_TABLES' 6 Query SET autocommit=0 6 Query INSERT INTO t2 VALUES (1, 0) 6 Query SELECT * FROM t2 WHERE id=0 FOR UPDATE 6 Query INSERT INTO t2 VALUES (1, 0) 6 Query INSERT INTO t2 VALUES (2, 0) 6 Query UPDATE t1 SET x=2 WHERE id=0 100618 10:39:42 5 Query INSERT INTO t1 VALUES (0, 0) 5 Query SET autocommit=1 6 Quit 5 Query DROP TABLE IF EXISTS t1 5 Query DROP TABLE IF EXISTS t2 5 Quit
[18 Jun 2010 8:43]
Tonci Grgin
Error log (I did the shutdown after successful test): 100618 10:33:48 [Note] Buffered information: Performance schema disabled (reason: start parameters). 100618 10:33:48 [Note] Plugin 'FEDERATED' is disabled. InnoDB: The InnoDB memory heap is disabled InnoDB: Mutexes and rw_locks use Windows interlocked functions 100618 10:33:49 InnoDB: highest supported file format is Barracuda. 100618 10:33:49 InnoDB Plugin 1.0.6 started; log sequence number 44278 100618 10:33:49 [Note] Event Scheduler: Loaded 0 events 100618 10:33:49 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: ready for connections. Version: '5.5.3-m3-community-log' socket: '' port: 5530 MySQL Community Server (GPL) 100618 10:40:08 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: Normal shutdown 100618 10:40:08 [Note] Event Scheduler: Purging the queue. 0 events 100618 10:40:08 InnoDB: Starting shutdown... 100618 10:40:09 InnoDB: Shutdown completed; log sequence number 50780 100618 10:40:09 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: Shutdown complete
[18 Jun 2010 8:56]
Tonci Grgin
And finally, the test itself, testDeadlockBatchBehavior() completes correctly, ie. exception is thrown where expected, junit run completes:
the part that breaks intentionally:
new Thread() {
public void run() {
try {
deadlockStmt.addBatch("INSERT INTO t2 VALUES (1, 0)");
deadlockStmt.addBatch("INSERT INTO t2 VALUES (2, 0)");
deadlockStmt.addBatch("UPDATE t1 SET x=2 WHERE id=0");
deadlockStmt.executeBatch();
} catch (SQLException sqlEx) {
sqlEx.printStackTrace();
}
}
}.run();
The part right after that executes (as can be seen in log):
this.stmt.executeUpdate("INSERT INTO t1 VALUES (0, 0)");
[18 Jun 2010 14:18]
Mark Matthews
There's definitely something strange going on here. On my machine (Mac OS/X SL), the current 5.5 release hangs indefinitely on this test.
[18 Jun 2010 14:24]
Tonci Grgin
Whatever it is it's not repeatable on *proper* box :-) Joke aside, Eric, please attach server error log if not complete crash dump... Without that we can not proceed.
[18 Jun 2010 16:22]
MySQL Verification Team
I tried 5.5.3 x64 + c/j 5.1.3 rev 945 on windows as Eric suggested. But the testsuite gets to a point then appears to hang, and the reason is this: | Sleep | 747 | | NULL | | Sleep | 745 | | NULL | | Sleep | 745 | | NULL | | Sleep | 743 | | NULL | | Sleep | 739 | | NULL | | Query | 688 | Waiting for table | DROP TABLE IF EXISTS t1 | | Sleep | 688 | | NULL | Some other transaction holds locks on the table t1, so we observe expected waiting: ---TRANSACTION 4173, not started, OS thread id 1804 MySQL thread id 137, query id 3444 127.0.0.1 root Waiting for table DROP TABLE IF EXISTS t1 ---TRANSACTION 4174, ACTIVE 829 sec, OS thread id 2576 5 lock struct(s), heap size 1216, 5 row lock(s), undo log entries 3 MySQL thread id 138, query id 3441 127.0.0.1 root This looks like a bug in the tests. There's no evidence of server crash here. If manually ran "kill 138" the testsuite continues.
[18 Jun 2010 17:44]
Mark Matthews
Shane, I see the issue now, at least with the testsuite (and have fixed the semantics so that the test will at least pass). However, I've also seen that the testsuite will stay lodged in this state essentially forever, and even when terminating the application, the two deadlocked connections will remain this way, essentially forever until human intervention, well...intervenes and KILLs one or the other. Does the MDL code do no deadlock detection, or timeout? Or is it supposed to, and it's just broken?
[18 Jun 2010 18:11]
MySQL Verification Team
Works after specifying "lock-wait-timeout=55" in my.ini the testsuite finished but failed testBug39956 "The used table type doesn't support AUTO_INCREMENT...." http://dev.mysql.com/doc/refman/5.5/en/server-system-variables.html#sysvar_lock_wait_timeo... Maybe the testsuite should set this variable dynamically on >=5.5.3 and deal with the error??
[28 Jun 2010 13:41]
Tonci Grgin
Guys, could it be engine-related? I see no reference to engine used. I did test on MyISAM, all went fine.
[18 Jul 2010 23:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[23 Aug 2010 8:41]
Tonci Grgin
Eric?
[23 Sep 2010 23:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
Description: The Connector/J test testsuite\regression\StatementRegressionTest.java is hanging when run against this server version due to the server crashing. Earlier releases of connector J have been tried and had the same issues, and the test has been tried against other server versions and has run without issue. There appear to be roughly 200 individual test cases in this suite and there isn't a way to run them individually, so I'm not clear which case is causing the crash. Below is a thread dump from the JVM and attached is the query log from the server. The issue happens every time and the results and logs are the same. The server is running as a windows service and after the test hangs waiting for response the status of the service is "stopped". test: [mkdir] Created dir: C:\CONNECTOR_TESTS\connector-java\5.1\branch_5_1\build\junit [echo] Running unit tests against jdbc:mysql://localhost/test?user=root&password=mypass with jvm java [mkdir] Created dir: C:\CONNECTOR_TESTS\connector-java\5.1\branch_5_1\build\junit\unitregress [mkdir] Created dir: C:\CONNECTOR_TESTS\connector-java\5.1\branch_5_1\build\junit\unitregress\report [junit] Running testsuite.regression.StatementRegressionTest Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_15-b04 mixed mode): "Thread-11" daemon prio=6 tid=0x000000000044cac0 nid=0x6f8 runnable [0x0000000007a9f000..0x0000000007a9fb60] at java.io.FileInputStream.readBytes(Native Method) at java.io.FileInputStream.read(FileInputStream.java:177) at org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java:92) at java.lang.Thread.run(Thread.java:595) "Thread-10" daemon prio=6 tid=0x000000000044cd70 nid=0x5e0 runnable [0x000000000799f000..0x000000000799f7e0] at java.io.FileInputStream.readBytes(Native Method) at java.io.FileInputStream.read(FileInputStream.java:194) at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) at java.io.BufferedInputStream.read1(BufferedInputStream.java:256) at java.io.BufferedInputStream.read(BufferedInputStream.java:313) - locked <0x0000000010133278> (a java.io.BufferedInputStream) at java.io.FilterInputStream.read(FilterInputStream.java:90) at org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java:92) at java.lang.Thread.run(Thread.java:595) "RMI TCP Accept-0" daemon prio=6 tid=0x000000000044b290 nid=0x670 runnable [0x0000000005b7f000..0x0000000005b7fae0] at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x0000000011c58288> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:450) at java.net.ServerSocket.accept(ServerSocket.java:421) at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340) at java.lang.Thread.run(Thread.java:595) "Timer-0" daemon prio=6 tid=0x000000000044afe0 nid=0x210 in Object.wait() [0x0000000005a7f000..0x0000000005a7fb60] at java.lang.Object.wait(Native Method) - waiting on <0x0000000011c58520> (a java.util.TaskQueue) at java.lang.Object.wait(Object.java:474) at java.util.TimerThread.mainLoop(Timer.java:483) - locked <0x0000000011c58520> (a java.util.TaskQueue) at java.util.TimerThread.run(Timer.java:462) "Low Memory Detector" daemon prio=6 tid=0x000000000044ad30 nid=0x7ec runnable [0x0000000000000000..0x00000000000000 00] "CompilerThread1" daemon prio=10 tid=0x0000000004f55f00 nid=0x7a0 waiting on condition [0x0000000000000000..0x00000 000057ae9b0] "CompilerThread0" daemon prio=10 tid=0x0000000004f55c30 nid=0xa14 waiting on condition [0x0000000000000000..0x00000 000056aea70] "AdapterThread" daemon prio=10 tid=0x0000000004f55960 nid=0xb24 waiting on condition [0x0000000000000000..0x0000000 000000000] "Signal Dispatcher" daemon prio=10 tid=0x000000000044aa80 nid=0x6e8 waiting on condition [0x0000000000000000..0x000 0000000000000] "Finalizer" daemon prio=8 tid=0x000000000044a7d0 nid=0x75c in Object.wait() [0x00000000053af000..0x00000000053af9e0 ] at java.lang.Object.wait(Native Method) - waiting on <0x0000000011c588a0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120) - locked <0x0000000011c588a0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x000000000044a520 nid=0x6a8 in Object.wait() [0x00000000052af000..0x0000000 0052afae0] at java.lang.Object.wait(Native Method) - waiting on <0x0000000011c58970> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:474) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x0000000011c58970> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x000000000044a270 nid=0xba0 runnable [0x000000000012e000..0x000000000012fa00] at java.lang.ProcessImpl.waitFor(Native Method) at org.apache.tools.ant.taskdefs.Execute.waitFor(Execute.java:549) at org.apache.tools.ant.taskdefs.Execute.execute(Execute.java:480) at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.executeAsForked(JUnitTask.java:1021) at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(JUnitTask.java:817) at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(JUnitTask.java:780) at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288) at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:105) at org.apache.tools.ant.Task.perform(Task.java:348) at org.apache.tools.ant.Target.execute(Target.java:357) at org.apache.tools.ant.Target.performTasks(Target.java:385) at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1329) at org.apache.tools.ant.Project.executeTarget(Project.java:1298) at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(DefaultExecutor.java:41) at org.apache.tools.ant.Project.executeTargets(Project.java:1181) at org.apache.tools.ant.Main.runBuild(Main.java:698) at org.apache.tools.ant.Main.startAnt(Main.java:199) at org.apache.tools.ant.launch.Launcher.run(Launcher.java:257) at org.apache.tools.ant.launch.Launcher.main(Launcher.java:104) "VM Thread" prio=10 tid=0x00000000004514f0 nid=0x128 runnable "VM Periodic Task Thread" prio=10 tid=0x0000000000451610 nid=0x8fc waiting on condition How to repeat: to run the java tests install jdk 1.5 and 1.6 install apache ant set the value of env var ANT_HOME to the ant dir set the value of env var JAVA_HOME to jdk 1.5 Start the individual failing suite in a manner similar to this passing in the correct paths ant "-Dcom.mysql.jdbc.testsuite.url=jdbc:mysql://localhost/test?us er=root&password=mypass" "-Dcom.mysql.jdbc.java6.java=C:/Program Files/Java/jdk1.6.0_10/bin/java.exe" "-Dcom.mysql. jdbc.java6.javac=C:/Program Files/Java/jdk1.6.0_10/bin/javac.exe" "-Dcom.mysql.jdbc.java6.rtjar=C:/Program Files/Ja va/jdk1.6.0_10/jre/lib/rt.jar" -Dtest=testsuite.regression.StatementRegressionTest test If necessary the connectors/server test platform which is already set up to run it may be used for debugging.