| Bug #7541 | Test failure: Hang in 'having' (using '--ps-protocol') | ||
|---|---|---|---|
| Submitted: | 27 Dec 2004 10:35 | Modified: | 23 Jan 2005 15:34 |
| Reporter: | Joerg Bruehe | Email Updates: | |
| Status: | Can't repeat | Impact on me: | |
| Category: | MySQL Server | Severity: | S1 (Critical) |
| Version: | 5.0.3-pre | OS: | Linux (Linux 2.4 / Athlon) |
| Assigned to: | Konstantin Osipov | CPU Architecture: | Any |
[27 Dec 2004 18:08]
Joerg Bruehe
I re-tried with a 'debug' binary, gave the run option '--debug', and I got the same result. Here is the end of 'master.trace':
=== cut ===
T@163851: <do_command
T@163851: >dispatch_command
T@163851: | >mysql_stmt_execute
T@163851: | | exec_query:: select sum(col1) from t1
group by col_t1
having col_t1 in (select sum(t2.col1) from t2
group by t2.col2, t2.col1 having t2.col1 = col_t1)
T@163851: | | >mysql_reset_thd_for_next_command
T@163851: | | <mysql_reset_thd_for_next_command
T@163851: | | >reset_stmt_for_execute
T@163851: | | <reset_stmt_for_execute
T@163851: | | >mysql_execute_command
T@163851: | | | >mysql_reset_errors
T@163851: | | | | >free_root
T@163851: | | | | | enter: root: 0x8d3cb0c flags: 0
T@163851: | | | | <free_root
T@163851: | | | <mysql_reset_errors
T@163851: | | | >check_grant
T@163851: | | | <check_grant
T@163851: | | | >open_and_lock_tables
T@163851: | | | | >open_tables
T@163851: | | | | | >init_alloc_root
T@163851: | | | | | | enter: root: 0xbe5ff17c
T@163851: | | | | | | >_mymalloc
T@163851: | | | | | | | enter: Size: 8040
T@163851: | | | | | | | exit: ptr: 0x8d63110
T@163851: | | | | | | <_mymalloc
T@163851: | | | | | <init_alloc_root
T@163851: | | | | | >open_table
T@163851: | | | | | | >hash_search
T@163851: | | | | | | | exit: found key at 1
T@163851: | | | | | | <hash_search
T@163851: | | | | | <open_table
T@163851: | | | | | >free_root
T@163851: | | | | | | enter: root: 0xbe5ff17c flags: 1
T@163851: | | | | | <free_root
T@163851: | | | | | >open_table
T@163851: | | | | | | >hash_search
T@163851: | | | | | | | exit: found key at 0
T@163851: | | | | | | <hash_search
T@163851: | | | | | <open_table
T@163851: | | | | | >free_root
T@163851: | | | | | | enter: root: 0xbe5ff17c flags: 1
T@163851: | | | | | <free_root
T@163851: | | | | | >free_root
T@163851: | | | | | | enter: root: 0xbe5ff17c flags: 0
T@163851: | | | | | | >_myfree
T@163851: | | | | | | | enter: ptr: 0x8d63110
T@163851: | | | | | | <_myfree
T@163851: | | | | | <free_root
T@163851: | | | | <open_tables
T@163851: | | | | >mysql_lock_tables
T@163851: | | | | | >_mymalloc
T@163851: | | | | | | enter: Size: 32
T@163851: | | | | | | exit: ptr: 0x8d41ef8
T@163851: | | | | | <_mymalloc
T@163851: | | | | | >lock_external
T@163851: | | | | | | >mi_lock_database
T@163851: | | | | | | | enter: lock_type: 0 old lock 2 r_locks: 0 w_locks: 0 global_changed: 1 open_count: 1 name: './test/t1.MYI'
T@163851: | | | | | | | >my_raid_lock
T@163851: | | | | | | | | enter: Fd: 18 start: 0 length: 0 MyFlags: 0
T@163851: | | | | | | | <my_raid_lock
T@163851: | | | | | | <mi_lock_database
T@163851: | | | | | | >mi_lock_database
T@163851: | | | | | | | enter: lock_type: 0 old lock 2 r_locks: 0 w_locks: 0 global_changed: 1 open_count: 1 name: './test/t2.MYI'
T@163851: | | | | | | | >my_raid_lock
T@163851: | | | | | | | | enter: Fd: 20 start: 0 length: 0 MyFlags: 0
T@163851: | | | | | | | <my_raid_lock
T@163851: | | | | | | <mi_lock_database
T@163851: | | | | | <lock_external
T@163851: | | | | | >thr_multi_lock
T@163851: | | | | | | lock: data: 0x8d41f08 count: 2
T@163851: | | | | | | >thr_lock
T@163851: | | | | | | | lock: data: 0x8d43144 thread: 163851 lock: 0x8d49960 type: 1
T@163851: | | | | | | | >check_locks
T@163851: | | | | | | | <check_locks
T@163851: | | | | | | | >mi_get_status
T@163851: | | | | | | | | info: key_file: 1024 data_file: 120
T@163851: | | | | | | | <mi_get_status
T@163851: | | | | | | | >check_locks
T@163851: | | | | | | | <check_locks
T@163851: | | | | | | <thr_lock
T@163851: | | | | | | >thr_lock
T@163851: | | | | | | | lock: data: 0x8d48cfc thread: 163851 lock: 0x8d656a0 type: 1
T@163851: | | | | | | | >check_locks
T@163851: | | | | | | | <check_locks
T@163851: | | | | | | | >mi_get_status
T@163851: | | | | | | | | info: key_file: 1024 data_file: 120
T@163851: | | | | | | | <mi_get_status
T@163851: | | | | | | | >check_locks
T@163851: | | | | | | | <check_locks
T@163851: | | | | | | <thr_lock
T@163851: | | | | | <thr_multi_lock
T@163851: | | | | <mysql_lock_tables
T@163851: | | | <open_and_lock_tables
T@163851: | | | >Query_cache::store_query
T@163851: | | | <Query_cache::store_query
T@163851: | | | >handle_select
T@163851: | | | | >mysql_select
T@163851: | | | | | >JOIN::prepare
T@163851: | | | | | | >setup_tables
T@163851: | | | | | | <setup_tables
T@163851: | | | | | | >setup_fields
T@163851: | | | | | | <setup_fields
T@163851: | | | | | | >setup_without_group
T@163851: | | | | | | | >setup_conds
T@163851: | | | | | | | <setup_conds
T@163851: | | | | | | <setup_without_group
T@163851: | | | | | | >JOIN::prepare
T@163851: | | | | | | | >setup_tables
T@163851: | | | | | | | <setup_tables
T@163851: | | | | | | | >setup_fields
T@163851: | | | | | | | <setup_fields
T@163851: | | | | | | | >setup_without_group
T@163851: | | | | | | | | >setup_conds
T@163851: | | | | | | | | <setup_conds
T@163851: | | | | | | | <setup_without_group
=== end of file ===
With test option '--gdb', I got this backtrace:
=== cut ===
Program received signal SIGSEGV, Segmentation fault.
0x08127510 in Item_ref::fix_fields(THD*, st_table_list*, Item**) (
this=0x8d59cd0, thd=0x8d3bdb8, tables=0x8d59578, reference=0x8d59e0c)
at item.cc:3028
3028 if (((*ref)->with_sum_func && name &&
(gdb) where
#0 0x08127510 in Item_ref::fix_fields(THD*, st_table_list*, Item**) (
this=0x8d59cd0, thd=0x8d3bdb8, tables=0x8d59578, reference=0x8d59e0c)
at item.cc:3028
#1 0x08138711 in Item_func::fix_fields(THD*, st_table_list*, Item**) (
this=0x8d59dc0, thd=0x8d3bdb8, tables=0x8d59578, ref=0x8d59f2c)
at item_func.cc:312
#2 0x0814f43f in Item_cond::fix_fields(THD*, st_table_list*, Item**) (
this=0x8d59e80, thd=0x8d3bdb8, tables=0x8d59578, ref=0x8d5e6e8)
at sql_list.h:323
#3 0x081effad in JOIN::prepare(Item***, st_table_list*, unsigned, Item*, unsigned, st_order*, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*) (this=0x8d5daa0, rref_pointer_array=0x8d5922c, tables_init=0x0, wild_num=0,
conds_init=0x0, og_num=0, order_init=0x0, group_init=0x0, having_init=0x0,
proc_param_init=0x0, select_lex_arg=0x0, unit_arg=0x8d59260)
at sql_select.cc:333
#4 0x0817e3ef in subselect_single_select_engine::prepare() (this=0x8d59ab8)
at item_subselect.cc:1130
#5 0x0817ad13 in Item_subselect::fix_fields(THD*, st_table_list*, Item**) (
this=0x8d483ac, thd_param=0x8d3bdb8, tables=0x0, ref=0x8d59ab8)
at item_subselect.cc:144
#6 0x081effad in JOIN::prepare(Item***, st_table_list*, unsigned, Item*, unsigned, st_order*, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*) (this=0x8d59ab8, rref_pointer_array=0x8d484b0, tables_init=0x0, wild_num=0,
conds_init=0x0, og_num=0, order_init=0x0, group_init=0x0, having_init=0x0,
proc_param_init=0x0, select_lex_arg=0x8d483ac, unit_arg=0x8d481f0)
at sql_select.cc:333
#7 0x081f489b in mysql_select(THD*, Item***, st_table_list*, unsigned, List<Item>&, Item*, unsigned, st_order*, st_order*, Item*, st_order*, unsigned long, select_result*, st_select_lex_unit*, st_select_lex*) (thd=0x8d3bdb8,
rref_pointer_array=0x8d484b0, tables=0x8d58ea0, wild_num=0, fields=@0x0,
conds=0x0, og_num=1, order=0x0, group=0x8d59078, having=0x8d59a18,
proc_param=0x0, select_options=310659584, result=0x8d59ad8,
unit=0x8d481f0, select_lex=0x8d483ac) at sql_select.cc:2015
#8 0x081efb06 in handle_select(THD*, st_lex*, select_result*) (thd=0x8d3bdb8,
lex=0x8d481e4, result=0x8d59ad8) at sql_select.cc:221
#9 0x081c2a7e in mysql_execute_command(THD*) (thd=0x8d3bdb8)
at sql_parse.cc:2191
#10 0x08217c97 in mysql_stmt_execute(THD*, char*, unsigned) (thd=0x8d3bdb8,
packet=0x8d54c72 "", packet_length=0) at sql_prepare.cc:1916
#11 0x081c0eac in dispatch_command(enum_server_command, THD*, char*, unsigned)
(command=COM_PROCESS_INFO, thd=0x8d3bdb8, packet=0x8d54c69 "E",
packet_length=10) at sql_parse.cc:1477
#12 0x081c08c6 in do_command(THD*) (thd=0x8d3bdb8) at sql_parse.cc:1319
#13 0x081bfd22 in handle_one_connection (arg=0x0) at sql_parse.cc:1051
#14 0x40150c60 in pthread_start_thread () from /lib/libpthread.so.0
#15 0x40150cdf in pthread_start_thread_event () from /lib/libpthread.so.0
(gdb)
[23 Jan 2005 15:34]
Konstantin Osipov
I can't repeat this problem in the latest 5.0. I tried with --valgrind as well. It must have been fixed already.
Description: Standard test suite hangs indefinitely in test 'having' if run with the option '--ps-protocol'. Report is: === cut === having [ fail ] Errors are (from /M50/push-5.0/mysql-test/var/log/mysqltest-time) : /M50/push-5.0/client/.libs/mysqltest: At line 259: unable to execute statement 'select sum(col1) from t1 group by col_t1 having col_t1 in (select sum(t2.col1) from t2 group by t2.col2, t2.col1 having t2.col1 = col_t1)': Lost connection to MySQL server during query (mysql_stmt_errno=2013 returned=1) (the last lines may be the most important ones) Ending Tests Shutting-down MySQL daemon master not cooperating with mysqladmin, will try manual kill ./mysql-test-run: line 1289: kill: (20842) - Kein passender Prozess gefunden master refused to die. Sending SIGKILL ./mysql-test-run: line 1293: kill: (20842) - Kein passender Prozess gefunden Master shutdown finished Slave shutdown finished === cut === I tried to kill the server using 'kill -8' or 'kill -11' to get a core dump, but it seemed immune against these two signals. A simple 'kill' worked, but that does not create a dump. However, I have a core timestamped from this test start (timestamp equals that of the screen output log file which I save using 'tee', granularity one minute). a backtrace from this file is: (gdb) where #0 0x4022d691 in kill () from /lib/libc.so.6 #1 0x40153511 in pthread_kill () from /lib/libpthread.so.0 #2 0x0829bfeb in write_core (sig=20896) at stacktrace.c:220 #3 0x0819da98 in handle_segfault (sig=20896) at mysqld.cc:1907 #4 0x40156895 in __pthread_sighandler () from /lib/libpthread.so.0 #5 <signal handler called> #6 0x0811e111 in Item_ref::fix_fields(THD*, st_table_list*, Item**) (this=0x4015af40, thd=0x8bf8770, tables=0x8c17fc0, reference=0x8c18974) at item.cc:3028 #7 0x0812f279 in Item_func::fix_fields(THD*, st_table_list*, Item**) (this=0x8c18808, thd=0x8bf8770, tables=0x8c17fc0, ref=0x8c18974) at item_func.cc:312 #8 0x081441cf in Item_cond::fix_fields(THD*, st_table_list*, Item**) (this=0x8c188c8, thd=0x8bf8770, tables=0x8c17fc0, ref=0x8bec0a0) at sql_list.h:323 #9 0x081e34ce in JOIN::prepare(Item***, st_table_list*, unsigned, Item*, unsigned, st_order*, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*) (this=0x8c18718, rref_pointer_array=0x8c18854, tables_init=0x0, wild_num=0, conds_init=0x0, og_num=0, order_init=0x0, group_init=0x0, having_init=0x0, proc_param_init=0x0, select_lex_arg=0xb, unit_arg=0x8c17ca8) at sql_select.cc:467 #10 0x081717c5 in subselect_single_select_engine::prepare() (this=0x8c18854) at item_subselect.cc:1130 #11 0x0816e5bf in Item_subselect::fix_fields(THD*, st_table_list*, Item**) (this=0x8c18718, thd_param=0x0, tables=0x40158bd0, ref=0x8bf8770) at item_subselect.cc:144 #12 0x081e34ce in JOIN::prepare(Item***, st_table_list*, unsigned, Item*, unsigned, st_order*, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*) (this=0x8c18718, rref_pointer_array=0x8c18854, tables_init=0x0, wild_num=0, conds_init=0x0, og_num=0, order_init=0x0, group_init=0x0, having_init=0x0, proc_param_init=0x0, select_lex_arg=0xb, unit_arg=0x8c0ae9c) at sql_select.cc:467 #13 0x081e7241 in mysql_select (thd=0x8bf8770, rref_pointer_array=0x8c0b15c, tables=0x8c178e8, wild_num=0, fields=@0x0, conds=0x0, og_num=1, order=0x0, group=0x8c17ac0, having=0x8c18460, proc_param=0x0, select_options=310659584, result=0x8bf8770, unit=0x8c0ae9c, select_lex=0x8c0b058) at sql_select.cc:2015 #14 0x081e2db5 in handle_select (thd=0x8bf8770, lex=0x8c0ae90, result=0x8c18520) at sql_select.cc:221 #15 0x081b7a02 in mysql_execute_command (thd=0x8bf8770) at sql_parse.cc:2191 #16 0x08205c7e in mysql_stmt_execute (thd=0x8bf8770, packet=0x8be265a "", packet_length=0) at sql_prepare.cc:1916 #17 0x081b3a84 in dispatch_command (command=COM_EXECUTE, thd=0x8bf8770, packet=0x8be2651 "E", packet_length=10) at sql_parse.cc:1477 #18 0x081b35b6 in do_command (thd=0x17) at sql_parse.cc:1319 #19 0x081b2a6c in handle_one_connection (arg=0xa) at sql_parse.cc:1051 #20 0x40150c60 in pthread_start_thread () from /lib/libpthread.so.0 (gdb) quit I cannot guarantee this core to be related to the hang, but I have no better analysis yet. I had similar hangs in the last days, but did not try to get a core dump then. So I suspect this problem was _not_ introduced by the latest changesets which are === cut === ChangeSet@1.1752, 2004-12-24 12:42:01+03:00, gluh@gluh.mysql.r18.ru Fix for bug #7467: sql_lex.c on HPUX fails to compile ChangeSet@1.1751, 2004-12-24 12:16:47+03:00, gluh@gluh.mysql.r18.ru Fix for bug: #7218: information_schema: errors in "tables" ChangeSet@1.1750, 2004-12-23 21:46:10+01:00, ingo@mysql.com Merge mysql.com:/home/mydev/mysql-5.0 into mysql.com:/home/mydev/mysql-5.0-wl2126 === cut === How to repeat: Run the test suite with '--ps-protocol'.