Bug #1204 Using HANDLER will goto to into loop...
Submitted: 5 Sep 2003 7:26 Modified: 18 Sep 2003 11:15
Reporter: Manuel Matonin Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:4.0.14 OS:Microsoft Windows (Windows)
Assigned to: Sergei Golubchik CPU Architecture:Any

[5 Sep 2003 7:26] Manuel Matonin
Description:
It seems there is loop problem while opening low-level table handler and flushing the same table...

How to repeat:
Create 2 separate threads with for loops in client.
Thread 1 executes FLUSH TABLE `table` and thread 2 executes HANDLER `table` OPEN.

Soon server side gets stuck while trying open table for HANDLER request...

Suggested fix:
open_tables ???
[5 Sep 2003 11:47] Indrek Siitan
Ok, I was able to repeat this with both MyISAM and InnoDB tables. Running
the following two PHP scripts in parallel should expose the problem (with
InnoDB almost immediately, with MyISAM it takes a little longer):

--- 8< ---

#!/usr/local/bin/php
<?

        mysql_connect("localhost","root","");
        mysql_select_db("bug");

        $i=0;
        while(1<2)
         {
                $i++;
                echo "Flush $i ... ";
                mysql_query("FLUSH TABLE category");
                echo "finished.\n";
         }

        mysql_close();

?>

--- 8< ---

#!/usr/local/bin/php
<?

        mysql_connect("localhost","root","");
        mysql_select_db("bug");

        $i=0;
        while(1<2)
         {
                $i++;
                echo "Iteration $i ... ";
                mysql_query("HANDLER category OPEN");
                mysql_query("HANDLER category READ `PRIMARY` FIRST");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category READ `PRIMARY` NEXT");
                mysql_query("HANDLER category CLOSE");
                echo "finished.\n";
         }

        mysql_close();

?>

--- 8< ---

Create info for the "category" table:

CREATE TABLE category (
  category_id int(11) NOT NULL default '0',
  owner_id int(11) default NULL,
  date_deleted datetime default NULL,
  title varchar(255) default NULL,
  PRIMARY KEY  (category_id)
) TYPE=[InnoDB|MyISAM];

INSERT INTO category VALUES (1,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (2,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (3,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (4,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (5,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (6,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (7,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (8,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (9,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (10,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (11,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (12,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (13,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (14,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (15,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (16,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (17,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (18,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (19,1,'2003-09-04 22:09:17','blah');
INSERT INTO category VALUES (20,1,'2003-09-04 22:09:17','blah');
[5 Sep 2003 11:53] Indrek Siitan
InnoDB crash backtrace (on FreeBSD 4.6): 

Program received signal SIGSEGV, Segmentation fault.
0x8194922 in row_search_for_mysql (buf=0xaa69828 "ÿ", mode=1,
    prebuilt=0x94ac860, match_mode=0, direction=0) at row0sel.c:2990
2990            clust_index = dict_table_get_first_index(index->table);
Current language:  auto; currently c
(gdb) bt
#0  0x8194922 in row_search_for_mysql (buf=0xaa69828 "ÿ", mode=1,
    prebuilt=0x94ac860, match_mode=0, direction=0) at row0sel.c:2990
#1  0x80e4da9 in ha_innobase::index_read (this=0xaa694a0, buf=0xaa69828 "ÿ",
    key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at ha_innodb.cc:2699
#2  0x80e5468 in ha_innobase::index_first (this=0xaa694a0, buf=0xaa69828 "ÿ")
    at ha_innodb.cc:2935
#3  0x804e2ad in mysql_ha_read (thd=0xaa65018, tables=0xaaad090, mode=RFIRST,
    keyname=0xaaad0e0 "PRIMARY", key_expr=0xa5a5a5a5,
    ha_rkey_mode=HA_READ_KEY_EXACT, cond=0x0, select_limit=1, offset_limit=0)
    at sql_handler.cc:161
#4  0x80875a3 in mysql_execute_command () at sql_parse.cc:2512
#5  0x8088325 in mysql_parse (thd=0xaa65018,
    inBuf=0xaaad028 "HANDLER category READ `PRIMARY` FIRST", length=37)
    at sql_parse.cc:2957
#6  0x80834d3 in dispatch_command (command=COM_QUERY, thd=0xaa65018,
    packet=0xaa73019 "", packet_length=38) at sql_parse.cc:1064
#7  0x8082f42 in do_command (thd=0xaa65018) at sql_parse.cc:939
#8  0x808267c in handle_one_connection (arg=0xaa65018) at sql_parse.cc:722
#9  0x2847341f in _thread_start () from /usr/lib/libc_r.so.4
#10 0xaaa8020 in ?? ()
#11 0xa9e2c00 in ?? ()
Error accessing memory address 0x2: Bad address.
[9 Sep 2003 10:17] Sergei Golubchik
Thank you for your bug report. This issue has been committed to our
source repository of that product and will be incorporated into the
next release.

If necessary, you can access the source repository and build the latest
available version, including the bugfix, yourself. More information 
about accessing the source trees is available at
    http://www.mysql.com/doc/en/Installing_source_tree.html

fixed in 4.1.16
[9 Sep 2003 10:28] Sergei Golubchik
4.0.16, sorry
[18 Sep 2003 1:17] Manuel Matonin
I think the first bug described by byself is not solved yet ? (if threadA has opened HANDLER on table A and threadB is trying to flush table A - and this is done continuously)

Try to create exact scenario as I described and soon mysql will go into loop because there is a refresh in progress:
T@5    : >dispatch_command
T@5    : | query: FLUSH TABLE kkk_test
T@5    : | >mysql_parse
T@5    : | | >mysql_init_query
T@5    : | | <mysql_init_query
T@5    : | | >Query_cache::send_result_to_client
T@5    : | | <Query_cache::send_result_to_client
T@5    : | | >add_table_to_list
T@5    : | | <add_table_to_list
T@5    : | | >mysql_execute_command
T@5    : | | | >Query_cache::flush
T@5    : | | | | >check_integrity
T@5    : | | | | | qcache: Query Cache not initialized
T@5    : | | | | <check_integrity
T@5    : | | | <Query_cache::flush
T@5    : | | | >close_cached_tables
T@5    : | | | | >remove_table_from_cache
T@5    : | | | | | >hash_search
T@5    : | | | | | | exit: found key at 0
T@5    : | | | | | <hash_search
T@5    : | | | | <remove_table_from_cache
T@5    : | | | | >close_old_data_files
T@5    : | | | | <close_old_data_files
T@5    : | | | | info: Waiting for others threads to close their open tables
T@6    : | info: query ready
T@6    : | >free_root
T@6    : | <free_root
T@6    : <dispatch_command
T@6    : >do_command
T@6    : | >vio_is_blocking
T@6    : | | exit: 1
T@6    : | <vio_is_blocking
T@6    : | >vio_read
T@6    : | | enter: sd=17488, buf=0263F3E8, size=4
T@6    : | | exit: 4
T@6    : | <vio_read
T@6    : | >vio_read
T@6    : | | enter: sd=17488, buf=0263F3E8, size=22
T@6    : | | exit: 22
T@6    : | <vio_read
T@6    : | info: Command on TCP/IP (17488) = 3 (Query)
T@6    : <do_command
T@6    : >dispatch_command
T@6    : | query: HANDLER kkk_test OPEN
T@6    : | >mysql_parse
T@6    : | | >mysql_init_query
T@6    : | | <mysql_init_query
T@6    : | | >Query_cache::send_result_to_client
T@6    : | | <Query_cache::send_result_to_client
T@6    : | | >add_table_to_list
T@6    : | | <add_table_to_list
T@6    : | | >mysql_execute_command
T@6    : | | | >open_tables
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | | >mi_close
T@6    : | | | | | | | enter: base: 268c210  reopen: 1  locks: 0
T@6    : | | | | | | | >_myfree
T@6    : | | | | | | | | enter: ptr: 26bbbd8
T@6    : | | | | | | | <_myfree
T@6    : | | | | | | | >flush_key_blocks_int
T@6    : | | | | | | | | enter: file: 4  blocks_used: 0  blocks_changed: 0
T@6    : | | | | | | | <flush_key_blocks_int
T@6    : | | | | | | | >my_close
T@6    : | | | | | | | | my: fd: 4  MyFlags: 0
T@6    : | | | | | | | | >_myfree
T@6    : | | | | | | | | | enter: ptr: 26147f8
T@6    : | | | | | | | | <_myfree
T@6    : | | | | | | | <my_close
T@6    : | | | | | | | >thr_lock_delete
T@6    : | | | | | | | <thr_lock_delete
T@6    : | | | | | | | >_myfree
T@6    : | | | | | | | | enter: ptr: 26adbc0
T@6    : | | | | | | | <_myfree
T@6    : | | | | | | | >my_close
T@6    : | | | | | | | | my: fd: 5  MyFlags: 0
T@6    : | | | | | | | | >_myfree
T@6    : | | | | | | | | | enter: ptr: 2647380
T@6    : | | | | | | | | <_myfree
T@6    : | | | | | | | <my_close
T@6    : | | | | | | | >_myfree
T@6    : | | | | | | | | enter: ptr: 268c210
T@6    : | | | | | | | <_myfree
T@6    : | | | | | | <mi_close
T@6    : | | | | | <close_old_data_files
T@5    : | | | | >reopen_tables
T@5    : | | | | <reopen_tables
T@5    : | | | <close_cached_tables
T@5    : | | | >send_ok
T@5    : | | | | packet_header: Memory: 3c0f648  Bytes: (4)
05 00 00 01 
T@5    : | | | | >net_flush
T@5    : | | | | | >vio_is_blocking
T@5    : | | | | | | exit: 1
T@5    : | | | | | <vio_is_blocking
T@5    : | | | | | >net_real_write
T@5    : | | | | | | >vio_write
T@5    : | | | | | | | enter: sd=17452, buf=0262D240, size=9
T@5    : | | | | | | | exit: 9
T@5    : | | | | | | <vio_write
T@5    : | | | | | <net_real_write
T@5    : | | | | <net_flush
T@5    : | | | <send_ok
T@5    : | | <mysql_execute_command
T@5    : | | >query_cache_end_of_result
T@5    : | | <query_cache_end_of_result
T@5    : | | >_myfree
T@5    : | | | enter: ptr: 0
T@5    : | | <_myfree
T@5    : | | >_myfree
T@5    : | | | enter: ptr: 0
T@5    : | | <_myfree
T@5    : | <mysql_parse
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
T@6    : | | | | | >hash_search
T@6    : | | | | | | exit: found key at 0
T@6    : | | | | | <hash_search
T@6    : | | | | | >close_old_data_files
T@6    : | | | | | <close_old_data_files
T@6    : | | | | <open_table
T@6    : | | | | >open_table
.......
.......
[18 Sep 2003 11:15] Sergei Golubchik
No, your original problem is solved.
FLASH TABLES originally was designed to wait until all open tables are closed (like when a SELECT is running, FLUSH TABLES will wait for it).
So, it does the same for HANDLER - that is, waits for HANDLER CLOSE to close the table. The bug was that HANDLER CLOSE did not signal FLUSH TABLE to continue.
[18 Sep 2003 23:19] Manuel Matonin
Thanks, but in which version it has been fixed ?