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:
None 
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
Description:
Hi!

mysqld-5.0 crashes in optimization of a simple SELECT. I suspect that OPTIMIZE TABLE does not lock the table properly, and the shared table info struct gets freed while queries are running on the table.

These messages may be associated with the bug:

Warning: Found locks from different threads in write: enter write_lock
Warning: Found locks from different threads in write: start of release lock

Regards,

Heikki

(gdb) print orig_table->s
$3 = (TABLE_SHARE *) 0x2b
(gdb)

heikki@hundin:~/test> perl ibtest3 > out3 &
[1] 20529
heikki@hundin:~/test> perl ibtest3a > out3a &
[2] 20532
heikki@hundin:~/test> perl ibtest4 > out4 &
[3] 20540
heikki@hundin:~/test> perl ibtest4a > out4a &
[4] 20547
heikki@hundin:~/test> perl ibtest7 > out7 &
[5] 20553
heikki@hundin:~/test> perl ibtest7a > out7a &
[6] 20558
heikki@hundin:~/test> perl ibtest9 > out9 &
[7] 20564
heikki@hundin:~/test> perl ibtest9a > out9a &
[8] 20568
heikki@hundin:~/test> perl ibtest9b > out9b &
[9] 20573
heikki@hundin:~/test> perl ibtest12 > out12 &
[10] 20577
heikki@hundin:~/test> perl ibtest12a > out12a &
[11] 20583
heikki@hundin:~/test> perl ibtest12b > out12b &
[12] 20588
heikki@hundin:~/test>

heikki@hundin:~/test> cat ibtest9b
############################################################################
#     Stress test for MySQL/Innobase combined database
#     (c) 2000 Innobase Oy & MySQL AB
#
############################################################################

use DBI;
use Benchmark;

$opt_loop_count = 200000;
$opt_loop_count2 = 50;

chomp($pwd = `pwd`); $pwd = "." if ($pwd eq '');
require "$pwd/bench-init.pl" || die "Can't read Configuration file: $!\n";

print "Generating random keys\n";
$random[$opt_loop_count] = 0;
$rnd_str[$opt_loop_count] = "a";

for ($i = 0; $i < $opt_loop_count; $i++) {

        $random[$i] = ($i * 63857) % $opt_loop_count;

        if (0 == ($random[$i] % 3)) {
                $rnd_str[$i] = "kjgclgrtfuylfluyfyufyulfulfyyulofuyolfyufyufuyfy
ufyufyufyufyyufujhfghd";
        } else { if (1 == ($random[$i] % 3)) {
                $rnd_str[$i] = "khd";
        } else { if (2 == ($random[$i] % 3)) {
                $rnd_str[$i] = "kh";
        }}}

        for ($j = 0; $j < (($i * 764877) % 20); $j++) {
                $rnd_str[$i] = $rnd_str[$i]."k";
        }
}

####
####  Connect
####

$dbh = $server->connect();

$dbh->do("set autocommit = 0");

for ($i = 0; $i < 100; $i++) {
        $k = 0;
        print "loop $i\n";

        for ($j = 1; $j < $opt_loop_count - 10; $j = $j + 2) {

                fetch_all_rows($dbh, "select b, c from ibtest09 where a < ".($j
% 100)." group by b order by a desc");

                if (0 == ($j % 37)) {
                        $dbh->do("commit");
                }

                if (0 == ($j % 533)) {
                        $dbh->do("rollback");
                }

                print fetch_all_rows($dbh, "select c from ibtest09 where c = '".
$rnd_str[$j - 67]."'");
                print fetch_all_rows($dbh, "select b from ibtest09 where b = '".
$rnd_str[$j - 688]."'");
                print fetch_all_rows($dbh, "select b, c from ibtest09 where c =
'".$rnd_str[$j - 67]."'");
                print fetch_all_rows($dbh, "select b, c from ibtest09 where b =
'".$rnd_str[$j - 622]."'");
                print fetch_all_rows($dbh, "select a, b, c from ibtest09 where c
 = '".$rnd_str[$j - 68]."' group by b, c order by a desc");
                print fetch_all_rows($dbh, "select a, b, c from ibtest09 where b
 = '".$rnd_str[$j - 644]."'");
                print fetch_all_rows($dbh, "select d, b, c from ibtest09 where c
 = '".$rnd_str[$j - 68]."'");
                print fetch_all_rows($dbh, "select t1.a, t.d, t.b, t.c from ibte
st09 t, ibtest09 t1 where t.b = '".$rnd_str[$j - 677]."' and t.a = t1.a and t.d
= t1.d group by t.b, t.c order by t.d, t1.a desc");

#               $dbh->disconnect;

#               $dbh = $server->connect();

                $dbh->do("set autocommit = 0");

                if (0 == (($j - 1) % 1000)) {
                        print "round $j\n";

                        $dbh->do("optimize table ibtest09")
                        || die $dbh->errstr;

                        print "table optimized\n";
                }
        }

        $dbh->do("commit");
}

$dbh->disconnect;                               # close connection

heikki@hundin:~/mysql-5.0/sql> gdb mysqld
GNU gdb 6.0
Copyright 2003 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i686-pc-linux-gnu"...
(gdb) run
Starting program: /home/heikki/mysql-5.0/sql/mysqld
[New Thread 16384 (LWP 20493)]
[New Thread 32769 (LWP 20495)]
[New Thread 16386 (LWP 20496)]
[New Thread 32771 (LWP 20497)]
[New Thread 49156 (LWP 20498)]
[New Thread 65541 (LWP 20499)]
050702 20:38:54  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Error: tablespace id 0 in file ./test/#sql-1c89_1e0.ibd is not sensible
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
050702 20:38:55  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 1 2118591188.
InnoDB: Doing recovery: scanned up to log sequence number 1 2123833856
InnoDB: Doing recovery: scanned up to log sequence number 1 2129076736
InnoDB: Doing recovery: scanned up to log sequence number 1 2134319616
InnoDB: Doing recovery: scanned up to log sequence number 1 2139562496
InnoDB: Doing recovery: scanned up to log sequence number 1 2144805376
InnoDB: Doing recovery: scanned up to log sequence number 1 2150048256
InnoDB: Doing recovery: scanned up to log sequence number 1 2155291136
InnoDB: Doing recovery: scanned up to log sequence number 1 2160534016
InnoDB: Doing recovery: scanned up to log sequence number 1 2165776896
InnoDB: Doing recovery: scanned up to log sequence number 1 2171019776
InnoDB: Doing recovery: scanned up to log sequence number 1 2176262656
InnoDB: Doing recovery: scanned up to log sequence number 1 2181505536
InnoDB: Doing recovery: scanned up to log sequence number 1 2186748416
050702 20:39:22  InnoDB: Starting an apply batch of log records to the database.
..
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19
20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46
 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7
3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 1 2191991296
InnoDB: Doing recovery: scanned up to log sequence number 1 2197234176
InnoDB: Doing recovery: scanned up to log sequence number 1 2202477056
InnoDB: Doing recovery: scanned up to log sequence number 1 2207719936
InnoDB: Doing recovery: scanned up to log sequence number 1 2212962816
InnoDB: Doing recovery: scanned up to log sequence number 1 2218205696
InnoDB: Doing recovery: scanned up to log sequence number 1 2223448576
InnoDB: Doing recovery: scanned up to log sequence number 1 2228691456
InnoDB: Doing recovery: scanned up to log sequence number 1 2233934336
InnoDB: Doing recovery: scanned up to log sequence number 1 2239177216
InnoDB: Doing recovery: scanned up to log sequence number 1 2244420096
InnoDB: Doing recovery: scanned up to log sequence number 1 2249662976
050702 20:40:16  InnoDB: Starting an apply batch of log records to the database.
..
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19
20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46
 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7
3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 1 2254905856
InnoDB: Doing recovery: scanned up to log sequence number 1 2260148736
InnoDB: Doing recovery: scanned up to log sequence number 1 2265391616
InnoDB: Doing recovery: scanned up to log sequence number 1 2270634496
InnoDB: Doing recovery: scanned up to log sequence number 1 2273531144
InnoDB: 8 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 301 row operations to undo
InnoDB: Trx id counter is 0 1138944
050702 20:40:54  InnoDB: Starting an apply batch of log records to the database.
..
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19
20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46
 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 7
3 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 53190755, file name ./binlog.000048
[New Thread 81926 (LWP 20535)]
InnoDB: Starting in background the rollback of uncommitted transactions
050702 20:41:14[New Thread 98311 (LWP 20536)]
  InnoDB: Rolling back trx with id 0 1138534, 100 rows to undo
[New Thread 114696 (LWP 20537)]
[New Thread 131081 (LWP 20538)]
050702 20:41:14  InnoDB: Started; log sequence number 1 2273531144
050702 20:41:14 [Note] Recovering after a crash using binlog
050702 20:41:14 [ERROR] Error in Log_event::read_log_event(): 'Found invalid eve
nt in binary log', data_len: 27, event_type: 20
050702 20:41:14 [Note] Starting crash recovery...
050702 20:41:14 [Note] Crash recovery finished.
[New Thread 147466 (LWP 20539)]
050702 20:41:14 [Warning] './mysql/host' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050702 20:41:14 [Warning] './mysql/user' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050702 20:41:14 [Warning] './mysql/db' had no or invalid character set, and defa
ult character set is multi-byte, so character column sizes may have changed
050702 20:41:14 [Warning] mysql.user table is not updated to new password format
; Disabling new password usage until mysql_fix_privilege_tables is run
050702 20:41:14 [Warning] './mysql/tables_priv' had no or invalid character set,
 and default character set is multi-byte, so character column sizes may have cha
nged
050702 20:41:14 [Warning] './mysql/columns_priv' had no or invalid character set
, and default character set is multi-byte, so character column sizes may have ch
anged
050702 20:41:14 [Warning] './mysql/func' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050702 20:41:14 [Note] /home/heikki/mysql-5.0/sql/mysqld: ready for connections.
Version: '5.0.9-beta-debug-log'  socket: '/home/heikki/bugsocket'  port: 3307  S
ource distribution
[New Thread 163851 (LWP 20543)]
[New Thread 180236 (LWP 20544)]
[New Thread 196621 (LWP 20545)]
[New Thread 213006 (LWP 20546)]
[New Thread 229391 (LWP 20550)]
[New Thread 245776 (LWP 20551)]

InnoDB: Rolling back of trx id 0 1138534 completed
050702 20:41:20  InnoDB: Rolling back trx with id 0 1138492, 3 rows to undo

InnoDB: Rolling back of trx id 0 1138492 completed
050702 20:41:21  InnoDB: Rolling back trx with id 0 1138474, 4 rows to undo

InnoDB: Rolling back of trx id 0 1138474 completed
050702 20:41:21  InnoDB: Rolling back trx with id 0 1138417, 13 rows to undo

InnoDB: Rolling back of trx id 0 1138417 completed
050702 20:41:21  InnoDB: Rolling back trx with id 0 1138200, 105 rows to undo

InnoDB: Rolling back of trx id 0 1138200 completed
050702 20:41:21  InnoDB: Rolling back trx with id 0 1136982, 7 rows to undo

InnoDB: Rolling back of trx id 0 1136982 completed
050702 20:41:21  InnoDB: Rolling back trx with id 0 1136448, 68 rows to undo

InnoDB: Rolling back of trx id 0 1136448 completed
050702 20:41:22  InnoDB: Rolling back trx with id 0 987385, 1 rows to undo

InnoDB: Rolling back of trx id 0 987385 completed
050702 20:41:22  InnoDB: Rollback of non-prepared transactions completed
[New Thread 262161 (LWP 20552)]
[New Thread 278546 (LWP 20556)]
[New Thread 294931 (LWP 20557)]
[New Thread 311316 (LWP 20561)]
[New Thread 327701 (LWP 20562)]
[New Thread 344086 (LWP 20563)]
[New Thread 360471 (LWP 20567)]
[New Thread 376856 (LWP 20571)]
[New Thread 393241 (LWP 20572)]
[New Thread 409626 (LWP 20576)]
[New Thread 426011 (LWP 20578)]
[New Thread 442396 (LWP 20581)]
[New Thread 458781 (LWP 20582)]
[New Thread 475166 (LWP 20584)]
[New Thread 491551 (LWP 20587)]
Warning: Found locks from different threads in write: enter write_lock
Warning: Found locks from different threads in write: start of release lock
[New Thread 507936 (LWP 20589)]
[New Thread 524321 (LWP 20592)]
[New Thread 540706 (LWP 20593)]

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 475166 (LWP 20584)]
0x08176203 in Field_string::type() const (this=0x8da1308) at field.h:982
982         return ((orig_table &&
(gdb) bt
#0  0x08176203 in Field_string::type() const (this=0x8da1308) at field.h:982
#1  0x082010ae in store_key (this=0x49d5603c, thd=0x8d74108,
    field_arg=0x8da1308, ptr=0x8d7ad68 "", null=0x0, length=450)
    at sql_select.h:465
#2  0x0820093d in store_key_item (this=0x49d5603c, thd=0x8d74108,
    to_field_arg=0x8da1308, ptr=0x8d7ad68 "", null_ptr_arg=0x0, length=450,
    item_arg=0x8d79878) at sql_select.h:517
#3  0x081ead31 in create_ref_for_key (join=0x8d79a60, j=0x8d7ac00,
    org_keyuse=0x8dcf998, used_tables=4611686018427387905)
    at sql_select.cc:4957
#4  0x081ea7b5 in get_best_combination (join=0x8d79a60) at sql_select.cc:4849
#5  0x081e4c7a in make_join_statistics (join=0x8d79a60, tables=0x0,
    conds=0x8d79910, keyuse_array=0x8d7a774) at sql_select.cc:2453
#6  0x081ded07 in JOIN::optimize() (this=0x8d79a60) at sql_select.cc:658
#7  0x081e3570 in mysql_select(THD*, Item***, st_table_list*, unsigned, List<Ite
m>&, Item*, unsigned, st_order*, st_order*, Item*, st_order*, unsigned long, sel
ect_result*, st_select_lex_unit*, st_select_lex*) (thd=0x8d74108,
    rref_pointer_array=0x8d74458, tables=0x8d79640, wild_num=0,
    fields=@0x8d743c0, conds=0x8d79910, og_num=0, order=0x0, group=0x0,
    having=0x0, proc_param=0x0, select_options=2156677632, result=0x8d79a50,
    unit=0x8d74158, select_lex=0x8d74338) at sql_select.cc:2031
#8  0x081dda62 in handle_select(THD*, st_lex*, select_result*, unsigned long) (
    thd=0x8d74108, lex=0x8d74148, result=0x8d79a50, setup_tables_done_option=0)
    at sql_select.cc:240
#9  0x081a52ef in mysql_execute_command(THD*) (thd=0x8d74108)
    at sql_parse.cc:2429
#10 0x081adc3d in mysql_parse(THD*, char*, unsigned) (thd=0x8d74108,
    inBuf=0x8d794a0 "select c from ibtest09 where c = 'kjgclgrtfuylfluyfyufyulfu
lfyyulofuyolfyufyufuyfyufyufyufyufyyufujhfghdkkkkkkkkk'", length=114)
    at sql_parse.cc:5387
#11 0x081a33f3 in dispatch_command(enum_server_command, THD*, char*, unsigned)
    (command=COM_QUERY, thd=0x8d74108,
    packet=0x8d81a69 "select c from ibtest09 where c = 'kjgclgrtfuylfluyfyufyulf
ulfyyulofuyolfyufyufuyfyufyufyufyufyyufujhfghdkkkkkkkkk'", packet_length=115)
    at sql_parse.cc:1674
#12 0x081a2bfa in do_command(THD*) (thd=0x8d74108) at sql_parse.cc:1477
#13 0x081a1d01 in handle_one_connection (arg=0x8d74108) at sql_parse.cc:1126
#14 0x40062f60 in pthread_start_thread () from /lib/i686/libpthread.so.0
#15 0x400630fe in pthread_start_thread_event () from /lib/i686/libpthread.so.0
---Type <return> to continue, or q <return> to quit---
#16 0x401f5327 in clone () from /lib/i686/libc.so.6
(gdb) info threads
  35 Thread 540706 (LWP 20593)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  33 Thread 507936 (LWP 20589)  0x40142b71 in kill () from /lib/i686/libc.so.6
* 31 Thread 475166 (LWP 20584)  0x08176203 in Field_string::type() const (
    this=0x8da1308) at field.h:982
  30 Thread 458781 (LWP 20582)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  28 Thread 426011 (LWP 20578)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  26 Thread 393241 (LWP 20572)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  23 Thread 344086 (LWP 20563)  0x083fe719 in safe_mutex_lock (mp=0x40abaa6c,
    file=0x84d7580 "../include/os0sync.ic", line=43) at thr_mutex.c:108
  22 Thread 327701 (LWP 20562)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  20 Thread 294931 (LWP 20557)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  18 Thread 262161 (LWP 20552)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  17 Thread 245776 (LWP 20551)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  15 Thread 213006 (LWP 20546)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  11 Thread 147466 (LWP 20539)  0x40142c47 in sigsuspend ()
   from /lib/i686/libc.so.6
  10 Thread 131081 (LWP 20538)  0x401ee851 in select ()
   from /lib/i686/libc.so.6
  9 Thread 114696 (LWP 20537)  0x401ee851 in select () from /lib/i686/libc.so.6
  8 Thread 98311 (LWP 20536)  0x401ee851 in select () from /lib/i686/libc.so.6
  6 Thread 65541 (LWP 20499)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  5 Thread 49156 (LWP 20498)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  4 Thread 32771 (LWP 20497)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  3 Thread 16386 (LWP 20496)  0x40065b94 in __pthread_sigsuspend ()
   from /lib/i686/libpthread.so.0
  2 Thread 32769 (LWP 20495)  0x401ecb66 in poll () from /lib/i686/libc.so.6
  1 Thread 16384 (LWP 20493)  0x401ee851 in select () from /lib/i686/libc.so.6
(gdb) thread 23
[Switching to thread 23 (Thread 344086 (LWP 20563))]#0  0x083fe719 in safe_mutex
_lock (mp=0x40abaa6c, file=0x84d7580 "../include/os0sync.ic", line=43)
    at thr_mutex.c:108
108       if (mp->count > 0 && pthread_equal(pthread_self(),mp->thread))
Current language:  auto; currently c
(gdb) bt
#0  0x083fe719 in safe_mutex_lock (mp=0x40abaa6c,
    file=0x84d7580 "../include/os0sync.ic", line=43) at thr_mutex.c:108
#1  0x0837c211 in os_fast_mutex_trylock (fast_mutex=0x40abaa6c)
    at os0sync.ic:43
#2  0x083714b0 in mutex_test_and_set (mutex=0x40abaa68) at sync0sync.ic:106
#3  0x083715a8 in mutex_enter_func (mutex=0x40abaa68,
    file_name=0x84ca944 "buf0buf.c", line=1088) at sync0sync.ic:257
#4  0x0833d450 in buf_page_get_gen (space=41156, offset=1482, rw_latch=2,
    guess=0x0, mode=10, file=0x84c78c0 "btr0cur.c", line=3434, mtr=0x49aa45fc)
    at buf0buf.c:1088
#5  0x08327b99 in btr_store_big_rec_extern_fields (index=0x40387e68,
    rec=0x432f99cb "kjgclgrtfu\200", offsets=0x49aa4acc,
    big_rec_vec=0x40539068, local_mtr=0x49aa4c6c) at btr0cur.c:3432
#6  0x08302a38 in row_ins_index_entry_low (mode=2, index=0x40387e68,
    entry=0x403c9e68, ext_vec=0x0, n_ext_vec=0, thr=0x403b8bb0)
    at row0ins.c:2051
#7  0x08302b16 in row_ins_index_entry (index=0x40387e68, entry=0x403c9e68,
    ext_vec=0x0, n_ext_vec=0, thr=0x403b8bb0) at row0ins.c:2100
#8  0x08302cb7 in row_ins_index_entry_step (node=0x403b8968, thr=0x403b8bb0)
    at row0ins.c:2179
#9  0x08302e80 in row_ins (node=0x403b8968, thr=0x403b8bb0) at row0ins.c:2311
#10 0x08303014 in row_ins_step (thr=0x403b8bb0) at row0ins.c:2415
#11 0x083048b0 in row_insert_for_mysql (mysql_rec=0x8cf58e8 "þB\003",
    prebuilt=0x403c9068) at row0mysql.c:1140
#12 0x0826f7dd in ha_innobase::write_row(char*) (this=0x8cf57a8,
    record=0x8cf58e8 "þB\003") at ha_innodb.cc:3227
#13 0x08203c28 in write_record(THD*, st_table*, st_copy_info*) (thd=0x8cc4ac0,
    table=0x8cc62c0, info=0x49aa54cc) at sql_insert.cc:1042
#14 0x082024d1 in mysql_insert(THD*, st_table_list*, List<Item>&, List<List<Item
> >&, List<Item>&, List<Item>&, enum_duplicates, bool) (thd=0x8cc4ac0,
    table_list=0x8d15960, fields=@0x8cc4f28, values_list=@0x8cc4f4c,
    update_fields=@0x8cc4f40, update_values=@0x8cc4f34, duplic=DUP_ERROR,
    ignore=false) at sql_insert.cc:480
#15 0x081a7678 in mysql_execute_command(THD*) (thd=0x8cc4ac0)
    at sql_parse.cc:3229
#16 0x081adc3d in mysql_parse(THD*, char*, unsigned) (thd=0x8cc4ac0,
    inBuf=0x8dfd2d8 "insert into blobt3 values (834, 5,'kjgclgrtfuylfluyfyufyulf
ulfyyulofuyolfyufyufuyfyufyufyufyufyyufujhfghd", 'k' <repeats 95 times>...,
    length=101689) at sql_parse.cc:5387
---Type <return> to continue, or q <return> to quit---
#17 0x081a33f3 in dispatch_command(enum_server_command, THD*, char*, unsigned)
    (command=COM_QUERY, thd=0x8cc4ac0,
    packet=0x8d1b979 "insert into blobt3 values (834, 5,'kjgclgrtfuylfluyfyufyul
fulfyyulofuyolfyufyufuyfyufyufyufyufyyufujhfghd", 'k' <repeats 95 times>...,
    packet_length=101690) at sql_parse.cc:1674
#18 0x081a2bfa in do_command(THD*) (thd=0x8cc4ac0) at sql_parse.cc:1477
#19 0x081a1d01 in handle_one_connection (arg=0x8cc4ac0) at sql_parse.cc:1126
#20 0x40062f60 in pthread_start_thread () from /lib/i686/libpthread.so.0
#21 0x400630fe in pthread_start_thread_event () from /lib/i686/libpthread.so.0
#22 0x401f5327 in clone () from /lib/i686/libc.so.6
(gdb) thread 33
[Switching to thread 33 (Thread 507936 (LWP 20589))]#0  0x40142b71 in kill ()
   from /lib/i686/libc.so.6
(gdb) bt
#0  0x40142b71 in kill () from /lib/i686/libc.so.6
#1  0x40065a1c in __pthread_restart_new () from /lib/i686/libpthread.so.0
#2  0x40066fd9 in __pthread_unlock () from /lib/i686/libpthread.so.0
#3  0x40064193 in pthread_mutex_unlock () from /lib/i686/libpthread.so.0
#4  0x083fe963 in safe_mutex_unlock (mp=0x860c800,
    file=0x84dff60 "safemalloc.c", line=491) at thr_mutex.c:162
#5  0x083e58d4 in _sanity (filename=0x849f620 "opt_range.cc", lineno=6067)
    at safemalloc.c:491
#6  0x083e493d in _mymalloc (size=32, filename=0x849f620 "opt_range.cc",
    lineno=6067, MyFlags=16) at safemalloc.c:131
#7  0x082510b1 in QUICK_RANGE_SELECT::reset() (this=0x49b16158)
    at opt_range.cc:6064
#8  0x0820eef9 in mysql_update(THD*, st_table_list*, List<Item>&, List<Item>&, I
tem*, unsigned, st_order*, unsigned long long, enum_duplicates, bool) (
    thd=0x8da5550, table_list=0x8db35a0, fields=@0x8da5808, values=@0x8da59c4,
    conds=0x8db3908, order_num=0, order=0x0, limit=18446744073709551615,
    handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:316
#9  0x081a74db in mysql_execute_command(THD*) (thd=0x8da5550)
    at sql_parse.cc:3190
#10 0x081adc3d in mysql_parse(THD*, char*, unsigned) (thd=0x8da5550,
    inBuf=0x8db3508 "update ibtest11a set B = 'kHdk' where A = 42669",
    length=47) at sql_parse.cc:5387
#11 0x081a33f3 in dispatch_command(enum_server_command, THD*, char*, unsigned)
    (command=COM_QUERY, thd=0x8da5550,
    packet=0x8dab4a9 "update ibtest11a set B = 'kHdk' where A = 42669",
    packet_length=48) at sql_parse.cc:1674
#12 0x081a2bfa in do_command(THD*) (thd=0x8da5550) at sql_parse.cc:1477
#13 0x081a1d01 in handle_one_connection (arg=0x8da5550) at sql_parse.cc:1126
#14 0x40062f60 in pthread_start_thread () from /lib/i686/libpthread.so.0
#15 0x400630fe in pthread_start_thread_event () from /lib/i686/libpthread.so.0
#16 0x401f5327 in clone () from /lib/i686/libc.so.6
(gdb) thread 31
[Switching to thread 31 (Thread 475166 (LWP 20584))]#0  0x08176203 in Field_stri
ng::type() const (this=0x8da1308) at field.h:982
982         return ((orig_table &&
Current language:  auto; currently c++
(gdb) bt
#0  0x08176203 in Field_string::type() const (this=0x8da1308) at field.h:982
#1  0x082010ae in store_key (this=0x49d5603c, thd=0x8d74108,
    field_arg=0x8da1308, ptr=0x8d7ad68 "", null=0x0, length=450)
    at sql_select.h:465
#2  0x0820093d in store_key_item (this=0x49d5603c, thd=0x8d74108,
    to_field_arg=0x8da1308, ptr=0x8d7ad68 "", null_ptr_arg=0x0, length=450,
    item_arg=0x8d79878) at sql_select.h:517
#3  0x081ead31 in create_ref_for_key (join=0x8d79a60, j=0x8d7ac00,
    org_keyuse=0x8dcf998, used_tables=4611686018427387905)
    at sql_select.cc:4957
#4  0x081ea7b5 in get_best_combination (join=0x8d79a60) at sql_select.cc:4849
#5  0x081e4c7a in make_join_statistics (join=0x8d79a60, tables=0x0,
    conds=0x8d79910, keyuse_array=0x8d7a774) at sql_select.cc:2453
#6  0x081ded07 in JOIN::optimize() (this=0x8d79a60) at sql_select.cc:658
#7  0x081e3570 in mysql_select(THD*, Item***, st_table_list*, unsigned, List<Ite
m>&, Item*, unsigned, st_order*, st_order*, Item*, st_order*, unsigned long, sel
ect_result*, st_select_lex_unit*, st_select_lex*) (thd=0x8d74108,
    rref_pointer_array=0x8d74458, tables=0x8d79640, wild_num=0,
    fields=@0x8d743c0, conds=0x8d79910, og_num=0, order=0x0, group=0x0,
    having=0x0, proc_param=0x0, select_options=2156677632, result=0x8d79a50,
    unit=0x8d74158, select_lex=0x8d74338) at sql_select.cc:2031
#8  0x081dda62 in handle_select(THD*, st_lex*, select_result*, unsigned long) (
    thd=0x8d74108, lex=0x8d74148, result=0x8d79a50, setup_tables_done_option=0)
    at sql_select.cc:240
#9  0x081a52ef in mysql_execute_command(THD*) (thd=0x8d74108)
    at sql_parse.cc:2429
#10 0x081adc3d in mysql_parse(THD*, char*, unsigned) (thd=0x8d74108,
    inBuf=0x8d794a0 "select c from ibtest09 where c = 'kjgclgrtfuylfluyfyufyulfu
lfyyulofuyolfyufyufuyfyufyufyufyufyyufujhfghdkkkkkkkkk'", length=114)
    at sql_parse.cc:5387
#11 0x081a33f3 in dispatch_command(enum_server_command, THD*, char*, unsigned)
    (command=COM_QUERY, thd=0x8d74108,
    packet=0x8d81a69 "select c from ibtest09 where c = 'kjgclgrtfuylfluyfyufyulf
ulfyyulofuyolfyufyufuyfyufyufyufyufyyufujhfghdkkkkkkkkk'", packet_length=115)
    at sql_parse.cc:1674
#12 0x081a2bfa in do_command(THD*) (thd=0x8d74108) at sql_parse.cc:1477
#13 0x081a1d01 in handle_one_connection (arg=0x8d74108) at sql_parse.cc:1126
#14 0x40062f60 in pthread_start_thread () from /lib/i686/libpthread.so.0
#15 0x400630fe in pthread_start_thread_event () from /lib/i686/libpthread.so.0
---Type <return> to continue, or q <return> to quit---
#16 0x401f5327 in clone () from /lib/i686/libc.so.6
(gdb)
(gdb) frame 0
#0  0x08176203 in Field_string::type() const (this=0x8da1308) at field.h:982
982         return ((orig_table &&
(gdb) list
977         :Field_longstr((char*) 0, len_arg, maybe_null_arg ? (uchar*) "": 0,
0,
978                        NONE, field_name_arg, table_arg, cs) {};
979
980       enum_field_types type() const
981       {
982         return ((orig_table &&
983                  orig_table->s->db_create_options & HA_OPTION_PACK_RECORD &&
984                  field_length >= 4) &&
985                 orig_table->s->frm_version < FRM_VER_TRUE_VARCHAR ?
986                 MYSQL_TYPE_VAR_STRING : MYSQL_TYPE_STRING);
(gdb) print orig_table
$1 = (st_table *) 0x49c60b6c
(gdb) print *orig_table
$2 = {s = 0x2b, file = 0x1f80, next = 0x0, prev = 0x0, in_use = 0x0,
  field = 0x0, record = {0x0, 0x0}, insert_values = 0x0, quick_keys = {
    map = 0}, used_keys = {map = 0}, keys_in_use_for_query = {map = 0},
  key_info = 0x0, next_number_field = 0x0, found_next_number_field = 0x0,
  rowid_field = 0x0, timestamp_field = 0x0, triggers = 0x0,
  pos_in_table_list = 0x0, group = 0x0, alias = 0x0, null_flags = 0x0,
  query_id = 0, quick_rows = {11160280164594278400, 16383,
    11160280164594278400, 16383, 18446744073709551615 <repeats 16 times>,
    0 <repeats 28 times>, 603702424191893504, 5315951890293764532,
    5315951237458713048, 5315951236384555040, 2339790808678400,
    5315954431840223232, 138514016936, 207, 184683593771, 4613570256177598588,
    5315954433077940324, 4613575581937045628, 18446744056529682440, 1,
    151398013844, 5315954431840223814}, const_key_parts = {1074164058,
    1237716456, 2148028423, 0, 4294902655, 4294902048, 4294967295, 136678490,
    1, 148246632, 43, 0, 1074164058, 20589, 32, 1237716548, 147802048, 0,
    1074181772, 1237716532, 135319540, 148103304, 1, 1237716644, 136204966,
    148103724, 1237716580, 147689452, 147802048, 0, 1074181772, 1237716612,
    1074164398, 1, 16777216, 65, 0, 148103568, 16777216, 0, 0, 147691824, 0,
    4294967295, 4294967295, 140560400, 13885220, 1237716676, 148099192,
    147691824, 1048575, 1237716772, 136205581, 1237717248, 0, 148099112,
    148405200, 0, 148099192, 1, 4294967295, 4294967295, 1237717024,
    1237717020}, quick_key_parts = {1237717016, 1237717020, 1237717016,
    1237717012, 8, 4294967292, 1, 0, 4294967205, 10426717, 0, 0, 148405200,
    4294967295, 4294967295, 1, 0, 1, 0, 1237716948, 136207120, 148103304, 0,
    148099112, 148098888, 0, 148099192, 1, 4294967295, 4294967295, 0, 0, 0,
    148098096, 148098888, 0, 2, 0, 343597056, 2598455214, 3758112767,
    1202590842, 1073715937, 288, 148405200, 89784320, 136678490, 35,
    1074156879, 43, 148099112, 0, 0, 0, 1237717676, 1237717652, 1075063464,
    32, 140459224, 1237716948, 135312265, 1237717084, 0, 1237717124},
  timestamp_field_type = 136205876, map = 1237717084, tablenr = 148099112,
  used_fields = 4294967295, temp_pool_slot = 4294967295, status = 1,
  db_stat = 0, derived_select_number = 1074158484, current_lock = 35,
  copy_blobs = 70 'F', maybe_null = 1237717652, null_row = 43 '+',
  force_index = 0 '\0', distinct = 0 '\0', const_table = 0 '\0',
  no_rows = 24 '\030', key_read = 16 '\020', no_keyread = -58 'Æ',
  locked_by_flush = 73 'I', locked_by_name = 7 '\a',
  fulltext_searched = 80 'P', no_cache = 8 '\b', clear_query_id = -128 '\200',
  auto_increment_field_not_null = 0 '\0', insert_or_update = 0 '\0',
  alias_name_used = 0 '\0', reginfo = {join_tab = 0x40066317,
---Type <return> to continue, or q <return> to quit---
    lock_type = 148099112, not_exists_optimize = 2, impossible_range = false},
  mem_root = {free = 0x8dc0fa8, used = 0x2, pre_alloc = 0x0,
    min_malloc = 148104536, block_size = 1237717124, block_num = 0,
    first_block_usage = 0, error_handler = 0x49c6107c}, grant = {
    grant_table = 0x49c61094, version = 138298598, privilege = 220,
    want_privilege = 148411880}, sort = {io_cache = 0x8dc0ec8,
    addon_buf = 0x8dc0fb0 "\003", addon_length = 148639296, addon_field = 0x0,
    unpack = 0, record_pointers = 0x20 <Address 0x20 out of bounds>,
    found_records = 21474838472}, share_not_to_be_used = {name_hash = {
      key_offset = 0, key_length = 135610832, records = 0,
      blength = 1078394880, current_record = 1237717140, flags = 148104304,
      array = {buffer = 0x8d3e190 "HfÔ\b", elements = 0,
        max_element = 1717986918, alloc_increment = 1076127334,
        size_of_element = 8}, get_key = 0x108, free = 0xffffffff,
      charset = 0xffffffff}, mem_root = {free = 0x0, used = 0x0,
      pre_alloc = 0x41, min_malloc = 0, block_size = 148104536,
      block_num = 148103568, first_block_usage = 1237717284,
      error_handler = 0x81e37b7 <get_quick_record_count+175>}, keynames = {
      count = 148104304, name = 0x8cd9700 "¨=E\b@µÓ\bÀJÌ\b¸=E\bààÓ\b\\\020ÆI",
      type_names = 0x41, type_lengths = 0x0}, fieldnames = {count = 0,
      name = 0x0, type_names = 0xffffffff, type_lengths = 0xffffffff},
    intervals = 0x0, blob_field = 0x8d3e470, default_values = 0x8d3cc30 "",
    comment = 0x1 <Address 0x1 out of bounds>, table_charset = 0x49c6110c,
    table_cache_key = 0x49c6110c "", db = 0x8d3e470 "",
    table_name = 0x1000000 <Address 0x1000000 out of bounds>, path = 0x0,
    keys_in_use = {map = 0}, keys_for_keyread = {map = 18446744069414584320},
    avg_row_length = 4294967295, raid_chunksize = 1237717876,
    version = 136202619, flush_version = 147691264, mysql_version = 148104304,
    timestamp_offset = 148137544, reclength = 148103724,
    min_rows = 18446744073709551615, max_rows = 5315957747554975745,
    db_type = 147691824, row_type = ROW_TYPE_DEFAULT, tmp_table = TMP_TABLE,
    blob_ptr_size = 0, null_bytes = 1, key_length = 0, fields = 1237717364,
    rec_buff_length = 135246679, keys = 1237717508, key_parts = 0,
    max_key_length = 1237717380, max_unique_length = 148099312,
    total_key_length = 0, uniques = 3087007744, null_fields = 1237729284,
    blob_fields = 135520341, varchar_fields = 1237717500,
    db_create_options = 1048575, db_options_in_use = 0,
    db_record_offset = 1074266112, raid_type = 0, raid_chunks = 2147483648,
    open_count = 16383, primary_key = 148099448, timestamp_field_offset = 1,
---Type <return> to continue, or q <return> to quit---
    next_number_index = 148097948, next_number_key_offset = 0,
    frm_version = 0 '\0', system = 0 '\0', crypted = 8 '\b',
    db_low_byte_first = 64 '@', crashed = -112 '\220', is_view = -31 'á',
    name_lock = -45 'Ó', replace_with_name_lock = 8 '\b'}}
(gdb) print *orig_table->s
Cannot access memory at address 0x2b
(gdb) print orig_table->s
$3 = (TABLE_SHARE *) 0x2b
(gdb)

How to repeat:
Run the ibtest stress test suite.
[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)