Bug #11704 | Found locks from different threads in write -> crash with OPTIMIZE table? | ||
---|---|---|---|
Submitted: | 2 Jul 2005 18:52 | Modified: | 20 Jun 2010 22:40 |
Reporter: | Heikki Tuuri | Email Updates: | |
Status: | Closed | Impact on me: | |
Category: | MySQL Server: Optimizer | Severity: | S2 (Serious) |
Version: | 5.0.9, 4.1 | OS: | Linux (Linux/x86) |
Assigned to: | CPU Architecture: | Any |
[2 Jul 2005 18:52]
Heikki Tuuri
[2 Jul 2005 18:55]
Heikki Tuuri
I am using innodb_locks_unsafe_for_binlog. # Example mysql config file. # Copy this file to c:\my.cnf to set global options # # One can use all long options that the program supports. # Run the program with --help to get a list of available options # This will be passed to all mysql clients [client] #default-character-set=utf8 socket=/home/heikki/bugsocket #socket=/tmp/mysqld.heikki port=3307 #password=my_password #port=3306 #socket=MySQL # Here is entries for some specific programs # The following values assume you have at least 32M ram # The MySQL server [mysqld] #innodb_locks_unsafe_for_binlog #sync-binlog=1 #innodb_support_xa=0 #log #innodb_table_locks=0 #skip-safemalloc #bdb-no-sync #skip-innodb server-id=1 default-character-set=utf8 #lower_case_table_names=1 language=/home/heikki/mysql-5.0/sql/share/english default-table-type=innodb log-bin=binlog set-variable = max_binlog_size=100M port=3307 socket=/home/heikki/bugsocket #skip-locking basedir=/home/heikki datadir=/home/heikki/data// #innodb_open_files=765 #set-variable = innodb_buffer_pool_awe_mem_mb=100 #set-variable = innodb_lock_wait_timeout=5 #innodb_force_recovery=5 #set-variable = innodb_thread_concurrency=8 #innodb_flush_method=fdatasync #innodb_fast_shutdown=0 # Uncomment the following row if you move the MySQL distribution to another # location #basedir = d:/mysql/ #set-variable = table_cache=256 #set-variable = sort_buffer_size=32M #set-variable = myisam_sort_buffer_size=384M #set-variable = read_buffer_size=32M #set-variable = read_rnd_buffer_size=32M #set-variable = tmp_table_size=384M #set-variable = thread_cache=8 #set-variable = thread_concurrency=2 #set-variable=key_buffer=35M #set-variable=long_query_time=5 set-variable=max_allowed_packet=8M #set-variable=low_priority_updates=1 #set-variable=query_cache_size=50M #set-variable=query_cache_limit=2M #set-variable=query_cache_type=1 # Uncomment the following if you are using InnoDB tables innodb_locks_unsafe_for_binlog innodb_file_per_table #set-variable = innodb_force_recovery=6 innodb_data_home_dir = /home/heikki/data #innodb_autoextend_increment = 20 innodb_data_file_path = ibdata1:10M:autoextend innodb_log_group_home_dir = /home/heikki/data # You can set .._buffer_pool_size up to 50 - 80 % # of RAM but beware of setting memory usage too high set-variable = innodb_buffer_pool_size=100M set-variable = innodb_additional_mem_pool_size=10M set-variable = innodb_file_io_threads=4 # Set .._log_file_size to 25 % of buffer pool size set-variable = innodb_log_file_size=125M set-variable = innodb_log_files_in_group=2 set-variable = innodb_log_buffer_size=8M innodb_flush_log_at_trx_commit=0 set-variable = innodb_lock_wait_timeout=50 # InnoDB does a full purge and an insert buffer merge # before a shutdown. May be slow hope to solve problem #set-variable = innodb_fast_shutdown=0 #set-variable = lower_case_table_names=1 #innodb_lock_wait_timeout=5 #innodb_thread_concurrency=500 [mysqldump] quick set-variable = max_allowed_packet=16M [mysql] #default-character-set=utf8 no-auto-rehash socket=/home/heikki/bugsocket port=3307 [mysqladmin] socket=/home/heikki/bugsocket port=3307 [isamchk] set-variable= key=16M [client_fltk]
[2 Jul 2005 19:13]
Heikki Tuuri
Hi! I changed OPTIMIZE TABLE to ALTER TABLE ... TYPE = INNODB. Now I get a lock wait timeout. Looks like OPTIMIZE is NOT internally an ALTER in 5.0. I am assigning this to Guilhem, as he implemented InnoDB OPTIMIZE in 4.1. Regards, Heikki [12] 20802 heikki@hundin:~/test> Lock wait timeout exceeded; try restarting transaction at ibtest9b line 79. [9] Exit 255 perl ibtest9b >out9b
[2 Jul 2005 19:59]
Guilhem Bichot
De-assigning it from me. If it crashes in 5.0 and not in 4.1, while I implemented in 4.1, then this problem is "open to all" for now.
[2 Jul 2005 22:28]
Heikki Tuuri
Guilhem, also 4.1 prints this: " Warning: Found locks from different threads in write: start of release lock " I do not get the other warnings I got with 5.0. There is probably something wrong with table locking in OPTIMIZE TABLE. Crashing mysqld takes some 1 - 200 minutes with 5.0. So far I have not been able to crash 4.1. Note that there is no TABLE_SHARE struct in 4.1. That is where the crash happened in 5.0. Regards, Heikki
[29 Aug 2005 17:18]
Heikki Tuuri
Three Perl programs
Attachment: 3PerlPrograms.txt (text/plain), 12.75 KiB.
[1 Sep 2005 10:18]
Sergey Petrunya
I don't know if this is related, but running the test on server under valgrind produces the following warnings: ==30665== Conditional jump or move depends on uninitialised value(s) ==30665== at 0x8400971: rec_get_deleted_flag (rem0rec.ic:588) ==30665== by 0x83AE1B3: row_search_for_mysql (row0sel.c:3861) ==30665== by 0x827BBAE: ha_innobase::index_read(char*, char const*, unsigned, ha_rkey_function) (ha_innodb.cc:3906) ==30665== by 0x8205BB5: join_read_always_key(st_join_table*) (sql_select.cc:9899) ==30665== by 0x8204CA4: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:9403) ==30665== by 0x82047B1: do_select(JOIN*, List<Item>*, st_table*, Procedure*) (sql_select.cc:9167) ==30665== by 0x81F4248: JOIN::exec() (sql_select.cc:1673) ==30665== by 0x81F5085: _Z12mysql_selectP3THDPPP4ItemP13st_table_listjR4ListIS1_ES2_jP8st_orderSB_S2_SB_mP13select_resultP18st_select_lex_unitP13st_select_lex (sql_select.cc:2093) ==30665== by 0x81EFF1A: handle_select(THD*, st_lex*, select_result*, unsigned long) (sql_select.cc:238) ==30665== by 0x81B7D91: mysql_execute_command(THD*) (sql_parse.cc:2436) ==30665== by 0x81C017E: mysql_parse(THD*, char*, unsigned) (sql_parse.cc:5450) ==30665== by 0x81B617D: dispatch_command(enum_server_command, THD*, char*, unsigned) (sql_parse.cc:1665) ==30665== by 0x81B5A88: do_command(THD*) (sql_parse.cc:1464) ==30665== by 0x81B4BFD: handle_one_connection (sql_parse.cc:1116) ==30665== by 0x1BA8ABBA: thread_wrapper (vg_libpthread.c:867) ==30665== by 0xB000F64F: do__quit (vg_scheduler.c:1872) it didn't crash yet for me under valgrind though.
[29 Sep 2005 22:00]
Brian Aker
You need to go into the handler and check to see if the table being used is not a part of any current transaction.
[12 Oct 2005 17:40]
Sergey Petrunya
The current mysql-5.0 doesn't crash. One still gets warnings like this though: Warning: Found locks from different threads in write: start of release lock The following patch makes the warning to go away: ===== ha_innodb.cc 1.271 vs edited ===== *** /home/psergey/mysql-5.0-bug11704-r2-debug/BitKeeper/tmp/bk_ha_innodb.cc-1.271_frswHM 2005-10-07 11:14:38 +04:00 --- edited/ha_innodb.cc 2005-10-12 13:52:59 +04:00 *************** *** 6753,6759 **** || thd->lex->sql_command == SQLCOM_CALL) && !thd->tablespace_op && thd->lex->sql_command != SQLCOM_TRUNCATE ! && thd->lex->sql_command != SQLCOM_CREATE_TABLE) { lock_type = TL_WRITE_ALLOW_WRITE; } --- 6753,6760 ---- || thd->lex->sql_command == SQLCOM_CALL) && !thd->tablespace_op && thd->lex->sql_command != SQLCOM_TRUNCATE ! && thd->lex->sql_command != SQLCOM_CREATE_TABLE ! && thd->lex->sql_command != SQLCOM_OPTIMIZE) /*psergey*/{ lock_type = TL_WRITE_ALLOW_WRITE; } ---patch ends--- but the client scripts still produce the "Can't find record in 'ibtest09' "(*) errors. The (*) errors are produced even when one comments out OPTIMIZE TABLE statement.
[12 Oct 2005 17:43]
Sergey Petrunya
The warnings are produced by this line in 1st client script: $dbh->do("update ibtest09 SET D = D + 1, I = 'f' where A =".($j/ 2 - 500)) and this query in 2nd client script: $dbh->do("update ibtest09 SET D = D + 1 where A =".(($j - 1) / 2 - 777))
[13 Oct 2005 14:21]
Sergey Petrunya
The 'record not found' error is caused by a bug in ha_innobase::position() when PK is defined over UTF-8 string. I have the fix, now running tests.
[15 Oct 2005 12:44]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/internals/31131
[16 Oct 2005 8:15]
Heikki Tuuri
Sergey, I tested what 5.0 does in OPTIMIZE TABLE. It uses TL_WRITE_ALLOW_READ to protect the table. That lock type is not converted to anything in ::store_lock(). I do not understand how your patch would fix the lock warnings. heikki@hundin:~/mysql-5.0/client> ./mysql test Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 1 to server version: 5.0.15-rc-debug-log Type 'help;' or '\h' for help. Type '\c' to clear the buffer. mysql> create table opt(a int not null primary key, b int) type = innodb; Query OK, 0 rows affected, 1 warning (0.02 sec) mysql> insert into opt values (1, 10); Query OK, 1 row affected (3.70 sec) mysql> insert into opt values (2, 11); Query OK, 1 row affected (2.30 sec) mysql> optimize table opt; +----------+----------+----------+----------+ | Table | Op | Msg_type | Msg_text | +----------+----------+----------+----------+ | test.opt | optimize | status | OK | +----------+----------+----------+----------+ 1 row in set (53.87 sec)
[16 Oct 2005 8:15]
Heikki Tuuri
Breakpoint 1, ha_innobase::store_lock(THD*, st_thr_lock_data**, thr_lock_type) (this=0x8c60860, thd=0x8c5f330, to=0x8c61278, lock_type=TL_WRITE) at ha_innodb.cc:6673 6673 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_pre built; (gdb) Continuing. Breakpoint 1, ha_innobase::store_lock(THD*, st_thr_lock_data**, thr_lock_type) (this=0x8c60860, thd=0x8c5f330, to=0x8c4c648, lock_type=TL_IGNORE) at ha_innodb.cc:6673 6673 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_pre built; (gdb) Continuing. Breakpoint 1, ha_innobase::store_lock(THD*, st_thr_lock_data**, thr_lock_type) (this=0x8c60860, thd=0x8c5f330, to=0x8c825e8, lock_type=TL_WRITE_ALLOW_READ) at ha_innodb.cc:6673 6673 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_pre built; (gdb) Continuing. Breakpoint 3, row_search_for_mysql (buf=0x8c60990 "ÿ", mode=1, prebuilt=0x40acfa68, match_mode=0, direction=0) at row0sel.c:3059 3059 dict_index_t* index = prebuilt->index; Current language: auto; currently c (gdb) Continuing. Breakpoint 2, ha_innobase::write_row(char*) (this=0x8c82d40, record=0x8c82e70 "ý\001") at ha_innodb.cc:3188 3188 row_prebuilt_t* prebuilt = (row_prebuilt_t*)innobase_prebuilt; Current language: auto; currently c++ (gdb) Continuing. Breakpoint 3, row_search_for_mysql (buf=0x8c60990 "ý\001", mode=0, prebuilt=0x40acfa68, match_mode=0, direction=1) at row0sel.c:3059 3059 dict_index_t* index = prebuilt->index; Current language: auto; currently c (gdb) Continuing. Breakpoint 2, ha_innobase::write_row(char*) (this=0x8c82d40, record=0x8c82e70 "ý\002") at ha_innodb.cc:3188 3188 row_prebuilt_t* prebuilt = (row_prebuilt_t*)innobase_prebuilt; Current language: auto; currently c++ (gdb) Continuing. Breakpoint 3, row_search_for_mysql (buf=0x8c60990 "ý\002", mode=0, prebuilt=0x40acfa68, match_mode=0, direction=1) at row0sel.c:3059 3059 dict_index_t* index = prebuilt->index; Current language: auto; currently c (gdb) Continuing. Breakpoint 1, ha_innobase::store_lock(THD*, st_thr_lock_data**, thr_lock_type) (this=0x8c60860, thd=0x8c5f330, to=0x8c61278, lock_type=TL_IGNORE) at ha_innodb.cc:6673 6673 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_pre built; Current language: auto; currently c++ (gdb) Continuing. Breakpoint 1, ha_innobase::store_lock(THD*, st_thr_lock_data**, thr_lock_type) (this=0x8c60860, thd=0x8c5f330, to=0x8c825e8, lock_type=TL_WRITE) at ha_innodb.cc:6673 6673 row_prebuilt_t* prebuilt = (row_prebuilt_t*) innobase_pre built; (gdb) Continuing.
[16 Oct 2005 8:47]
Heikki Tuuri
The Valgrind warning was probably fixed by: http://bugs.mysql.com/bug.php?id=12947
[16 Oct 2005 8:55]
Heikki Tuuri
Sergey, strange how the bug in UTF-8 column prefix indexes in ::store_key_val_for_row() has escaped our tests so long. I have run those Perl tests with default_character_set=utf8 but I did not see the warning. Thank you for noticing the UTF-8 bug. It should probably be fixed also for true VARCHAR. The bug probably is also in 4.1. Regards, Heikki
[16 Oct 2005 9:31]
Heikki Tuuri
Sergey, I created a separate bug report http://bugs.mysql.com/bug.php?id=14056 of the UTF-8 column prefix problem and assigned it to Jan Lindström. Regards, Heikki
[20 Oct 2005 10:52]
Sergey Petrunya
Heikki, OPTIMIZE TABLE does use TL_WRITE_ALLOW_WRITE. Here is how one can repeat on a server without my patch: 1. Start the server 2. From the client, run: create table opt(a int not null primary key, b int) type = innodb; insert into opt values (1, 10); insert into opt values (2, 11) 3. Stop the server. 4. Start gdb Add these breakpoints: b thr_lock commands silent printf "LOCK: %s\n", ((st_table*)(data->debug_print_param))->alias p lock_type cont end b thr_unlock commands silent printf "UNLOCK: %s\n", ((st_table*)(data->debug_print_param))->alias cont end b ha_innobase::store_lock commands silent printf "STORE_LOCK:\n" p lock_type cont end ### put this breakpoint at "*to++= &lock;" line in ha_innobase::store_lock: b ha_innodb.cc:6777 commands silent printf "STORED:" print lock.type cont end 5. Run mysqld from gdb. 6. From the client, run optimize table opt; 7. In gdb output see: ... [Switching to Thread 163851 (LWP 8437)] Current language: auto; currently c++ STORE_LOCK: $297 = TL_WRITE STORED:$298 = TL_WRITE_ALLOW_WRITE Current language: auto; currently c LOCK: opt $299 = TL_WRITE_ALLOW_WRITE Current language: auto; currently c++ STORE_LOCK: $300 = TL_IGNORE STORED:$301 = TL_WRITE_ALLOW_WRITE HA_ADMIN_TRY_ALTER Current language: auto; currently c UNLOCK: opt Current language: auto; currently c++ STORE_LOCK: $302 = TL_WRITE_ALLOW_READ STORED:$303 = TL_WRITE_ALLOW_READ Current language: auto; currently c LOCK: opt $304 = TL_WRITE_ALLOW_READ Current language: auto; currently c++ STORE_LOCK: $305 = TL_IGNORE STORED:$306 = TL_WRITE_ALLOW_READ Current language: auto; currently c UNLOCK: opt STORE_LOCK: $307 = TL_WRITE STORED:$308 = TL_WRITE_ALLOW_WRITE Current language: auto; currently c LOCK: opt $309 = TL_WRITE_ALLOW_WRITE UNLOCK: opt which proves that TL_WRITE_ALLOW_WRITE is used. mysql_lock_abort() is called after the last lock, and (see changeset comment in my commit email for complete description).
[20 Oct 2005 12:27]
Heikki Tuuri
Sergey, ok. Though I do not understand how and why lock_abort() upgrades the lock TL_WRITE_ALLOW_WRITE to TL_WRITE_ONLY. Regards, Heikki
[24 Oct 2005 20:22]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/internals/31403
[24 Oct 2005 20:35]
Sergey Petrunya
Fix pushed into 5.0.16 tree. The fix only fixes the "Found locks ..." warnings/possible crashes. The "Record not found" problem will be addressed separately in BUG#14056. Fix description: Running OPTIMIZE TABLE and other data-updating statements concurrently on an InnoDB table could cause a crash or the following warnings in the error log: Warning: Found locks from different threads in write: enter write_lock Warning: Found locks from different threads in write: start of release lock
[1 Nov 2005 19:22]
Paul DuBois
Noted in 5.0.16 changelog.
[5 May 2010 15:17]
Bugs System
Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[6 May 2010 1:28]
Paul DuBois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.
[6 May 2010 1:29]
Paul DuBois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.
[28 May 2010 5:59]
Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)
[28 May 2010 6:28]
Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[28 May 2010 6:56]
Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[30 May 2010 0:32]
Paul DuBois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.
[17 Jun 2010 12:02]
Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:44]
Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 13:30]
Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)