Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Minor
-
Resolution: Fixed
-
Affects Version/s: None
-
Fix Version/s: None
-
Component/s: None
-
Labels:
-
Environment:I am testing up to revno 4594 on mysql-5-6-leveldb
Description
This is the output from mtr when the test hangs.
$ ./mysql-test-run.pl leveldb
Logging: ./mysql-test-run.pl leveldb
2013-02-08 11:41:28 11898 [Note] Plugin 'FEDERATED' is disabled.
2013-02-08 11:41:28 11898 [Note] Binlog end
2013-02-08 11:41:28 11898 [Note] Shutting down plugin 'MyISAM'
2013-02-08 11:41:28 11898 [Note] Shutting down plugin 'CSV'
MySQL Version 5.6.9
Checking supported features...
- skipping ndbcluster
- SSL connections supported
Collecting tests...
Removing old var directory...
Creating var directory '/home/mcallaghan/b/mysql-5.6-leveldb/mysql-test/var'...
Installing system database...
Using server port 52391
==============================================================================
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
worker[1] Trying to dump core for [mysqltest - pid: 11949, winpid: 11949]
worker[1] Trying to dump core for [mysqld.1 - pid: 11925, winpid: 11925]
main.leveldb [ fail ] timeout after 900 seconds
Test ended at 2013-02-08 11:57:13
Test case timeout after 900 seconds
== /home/mcallaghan/b/mysql-5.6-leveldb/mysql-test/var/log/leveldb.log ==
#
create table t48(pk int primary key auto_increment, col1 varchar(12)) engine=leveldb;
set autocommit=0;
truncate table t48;
set autocommit=1;
drop table t48;
#
# MDEV-4059: LevelDB: query waiting for a lock cannot be killed until query timeout exceeded
#
create table t49 (pk int primary key, a int) engine=LevelDB;
insert into t49 values (1,10),(2,20);
begin;
update t49 set a = 100 where pk = 1;
connect con1,localhost,root,,;
set leveldb_lock_wait_timeout=5000;
set @var1= to_seconds(now());
update t49 set a = 1000 where pk = 1;
connect con2,localhost,root,,;
kill query 5;
connection con1;
== /home/mcallaghan/b/mysql-5.6-leveldb/mysql-test/var/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/home/mcallaghan/b/mysql-5.6-leveldb/mysql-test/var/tmp/mysqld.1.sock' (111)
Gliffy Diagrams
Attachments
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
Hi Mark,
Sergey will probably respond soon, but if you are testing right now, maybe it makes sense to revert to revno 4592. The last one somehow tested was 4591 (mainly tests were run on a earlier revision, after range scans implementation, but revno 4591 had at least some coverage when we were re-checking remaining known bugs). 4592 looks innocent, it's just comment cleanup, but the later commits were last minute changes, apparently they have some problems.
Reproducible on my machine as well.
Further attempts to kill the query also don't help:
mysql> show processlist;
-------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
-------------------------------------------------------------------------------------+
| 2 | root | localhost | test | Sleep | 56 | NULL | |
| 5 | root | localhost | test | Query | 56 | updating | update t49 set a = 1000 where pk = 1 |
| 6 | root | localhost | test | Sleep | 56 | NULL | |
| 7 | root | localhost:35234 | NULL | Query | 0 | cleaning up | show processlist |
-------------------------------------------------------------------------------------+
4 rows in set (0.00 sec)
mysql> kill query 5;
Query OK, 0 rows affected (0.00 sec)
mysql> show processlist;
-------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
-------------------------------------------------------------------------------------+
| 2 | root | localhost | test | Sleep | 81 | NULL | |
| 5 | root | localhost | test | Query | 81 | updating | update t49 set a = 1000 where pk = 1 |
| 6 | root | localhost | test | Sleep | 81 | NULL | |
| 7 | root | localhost:35234 | NULL | Query | 0 | cleaning up | show processlist |
-------------------------------------------------------------------------------------+
I've used incorrect "#ifdef XXX" statements, and it seems the server got compiled in a way that uses un-interruptible sleep (this is what is used in the unit test). Will have a fix shortly.
Should be fixed now. Please re-open if not.
Before the hang ...
$ ../client/mysql -uroot -Svar/tmp/mysqld.1.sock -e 'show processlist'
---
----------------------------------------------------------------------------+---
----------------------------------------------------------------------------+---
----------------------------------------------------------------------------+Thread stacks during the hang
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1 0x000000000057049f in inline_mysql_cond_wait (mutex=0x12105a0, that=0x1213280) at /home/mcallaghan/b/mysql-5.6-leveldb/include/mysql/psi/mysql_thread.h:1162
#2 block_until_new_connection () at /home/mcallaghan/b/mysql-5.6-leveldb/sql/mysqld.cc:2588
#3 one_thread_per_connection_end (thd=0x2201690, block_pthread=true) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/mysqld.cc:2667
#4 0x000000000066c056 in do_handle_one_connection (thd_arg=<optimized out>) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_connect.cc:976
#5 0x000000000066c0e9 in handle_one_connection (arg=<optimized out>) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_connect.cc:885
#6 0x00007fbb5e80ee9a in start_thread (arg=0x7fbb55ef9700) at pthread_create.c:308
#7 0x00007fbb5dd29cbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#8 0x0000000000000000 in ?? ()
#0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:215
#1 0x0000000000a3a82a in inline_mysql_cond_timedwait (abstime=0x7fbb55f37510, mutex=<optimized out>, that=<optimized out>)
at /home/mcallaghan/b/mysql-5.6-leveldb/include/mysql/psi/mysql_thread.h:1199
#2 LockTable::get_lock (this=<optimized out>, pins=0x7fbb44037580, key=0x7fbb44036540 "<", keylen=8, timeout_sec=5000)
at /home/mcallaghan/b/mysql-5.6-leveldb/storage/leveldb/ldb_locks.cc:207
#3 0x0000000000a3685f in ha_leveldb::get_row_by_rowid (this=0x7fbb440349f0, pk_tuple_for_lookup=<optimized out>, buf=0x7fbb44034ce0 "\377")
at /home/mcallaghan/b/mysql-5.6-leveldb/storage/leveldb/ha_leveldb.cc:1424
#4 0x0000000000a36c7a in ha_leveldb::index_read_map (this=0x7fbb440349f0, buf=0x7fbb44034ce0 "\377", key=<optimized out>, keypart_map=<optimized out>, find_flag=HA_READ_KEY_EXACT)
at /home/mcallaghan/b/mysql-5.6-leveldb/storage/leveldb/ha_leveldb.cc:1091
#5 0x000000000057925f in ha_index_read_map (find_flag=<optimized out>, keypart_map=<optimized out>, key=<optimized out>, buf=<optimized out>, this=0x7fbb440349f0)
at /home/mcallaghan/b/mysql-5.6-leveldb/sql/handler.cc:2668
#6 handler::read_range_first (this=0x7fbb440349f0, start_key=<optimized out>, end_key=<optimized out>, eq_range_arg=<optimized out>, sorted=<optimized out>)
at /home/mcallaghan/b/mysql-5.6-leveldb/sql/handler.cc:6561
#7 0x0000000000577ee5 in handler::multi_range_read_next (this=0x7fbb440349f0, range_info=0x7fbb55f37798) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/handler.cc:5732
#8 0x0000000000790db2 in QUICK_RANGE_SELECT::get_next (this=0x7fbb48008d60) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/opt_range.cc:10407
#9 0x00000000007b198b in rr_quick (info=0x7fbb55f378a0) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/records.cc:367
#10 0x0000000000700403 in mysql_update (thd=0x21f33c0, table_list=0x7fbb48004cf0, fields=..., values=..., conds=0x7fbb48005a60, order_num=0, order=0x7fbb55f378a0, limit=18446744073709551615,
handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7fbb55f38620, updated_return=0x7fbb55f38630) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_update.cc:727
#11 0x000000000069638f in mysql_execute_command (thd=0x21f33c0) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_parse.cc:3213
#12 0x0000000000699970 in mysql_parse (thd=0x21f33c0, parser_state=<optimized out>, length=<optimized out>, rawbuf=<optimized out>)
at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_parse.cc:6117
#13 0x000000000069b9cb in mysql_parse (parser_state=0x7fbb55f392b0, length=36, rawbuf=0x7fbb48004bf0 "update t49 set a = 1000 where pk = 1", thd=0x21f33c0)
at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_parse.cc:6017
#14 dispatch_command (command=<optimized out>, thd=0x21f33c0, packet=<optimized out>, packet_length=36) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_parse.cc:1312
#15 0x000000000066c015 in do_handle_one_connection (thd_arg=<optimized out>) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_connect.cc:969
#16 0x000000000066c0e9 in handle_one_connection (arg=<optimized out>) at /home/mcallaghan/b/mysql-5.6-leveldb/sql/sql_connect.cc:885
#17 0x00007fbb5e80ee9a in start_thread (arg=0x7fbb55f3a700) at pthread_create.c:308
#18 0x00007fbb5dd29cbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#19 0x0000000000000000 in ?? ()