Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Major
-
Resolution: Fixed
-
Affects Version/s: None
-
Fix Version/s: None
-
Component/s: None
-
Labels:
Description
We've managed to reproduce a bug we hit in production some weeks ago. It occurs
in the query cache while doing selects from multiple connections.
Here's the full gdb traceback:
Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffe92fe700 (LWP 29307)]
0x00007ffff61e9f55 in raise () from /lib64/libc.so.6
(gdb) bt full
#0 0x00007ffff61e9f55 in raise () from /lib64/libc.so.6
No symbol table info available.
#1 0x00007ffff61eb3d8 in abort () from /lib64/libc.so.6
No symbol table info available.
#2 0x00007ffff61e2f42 in ?? () from /lib64/libc.so.6
No symbol table info available.
#3 0x00007ffff61e2ff2 in __assert_fail () from /lib64/libc.so.6
No symbol table info available.
#4 0x00000000005bee14 in Query_cache::store_query (this=0x1495ce0, thd=0x1f20010, tables_used=0x7fffd4021b18)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_cache.cc:1386
tot_length = 140737105610912
_PRETTY_FUNCTION_ = "void Query_cache::store_query(THD*, TABLE_LIST*)"
local_tables = 1
query = 0x5a3d8a "\211\330H\203\304\070[]ÃÂUH\211\345H\203\354\060H\211}\370\211u\364\211U\360\211M\354L\211E\340L\211M\330H\213E\370\213U\364\211\020H\213E\370\213U\360\211P\004H\213E\370\213U\354\211P\bH\213E\370H\213U\340H\211P\020H\213E\370H\213U\330H\211P\030H\213E\370\306@ "
query_length = 140737105610944
tables_type = 0 '\000'
db_stack_frame =
#5 0x000000000060af7a in execute_sqlcom_select (thd=0x1f20010, all_tables=0x7fffd4021b18)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc:4620
lex = 0x7fffd401ca78
result = 0x7fffd4019ba0
res = false
#6 0x00000000006044da in mysql_execute_command (thd=0x1f20010) at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc:2189
privileges_requested = 1
res = 0
lex = 0x7fffd401ca78
db_stack_frame =
_FUNCTION_ = "mysql_execute_command"
up_result = 0
_PRETTY_FUNCTION_ = "int mysql_execute_command(THD*)"
select_lex = 0x7fffd401d200
first_table = 0x7fffd4021b18
all_tables = 0x7fffd4021b18
unit = 0x7fffd401cb28
have_table_map_for_update = false
#7 0x00000000008db161 in mysql_open_cursor (thd=0x1f20010, result=0x7fffd4005f08, pcursor=0x7fffd4005f68)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_cursor.cc:118
save_result = 0x7fffd40226f8
result_materialize = 0x7fffd4019ba0
lex = 0x7fffd401ca78
rc = 0
#8 0x0000000000623bd8 in Prepared_statement::execute (this=0x7fffd4005e50, expanded_query=0x7fffe92fd510, open_cursor=true)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_prepare.cc:3869
stmt_backup = {<ilink> = {_vptr.ilink = 0xcd3950, prev = 0x0, next = 0x0}, <Query_arena> = {_vptr.Query_arena = 0xcd3980, free_list = 0x7fffe92fd2f0,
mem_root = 0xc74389, is_backup_arena = false, is_reprepared = false, state = 32767}, id = 0, mark_used_columns = MARK_COLUMNS_READ, name =
\310H\211u\300\211U\274H\215E\320H\211\301\272
{", length = 8610247264}, lex = 0x1f222e8,
query_string = {string =
, cs = 0x1491140}, base_query =
{Ptr = 0x0, str_length = 0, Alloced_length = 0, extra_alloc = 0, alloced = false, str_charset = 0x135f260}, db = 0x7fffe92fd3b0 "", db_length = 140737105613680, query_cache_is_applicable = -98 '\236'}
old_stmt_arena = 0x1f20028
saved_cur_db_name_buf = "\220W\000\324\377\177\000\000\260\323/\351\377\177\000\000@\324/\351\377\177\000\000E\331a\000\000\000\000\000\360\323/\351\377\177\000\000\020\325/\351\377\177\000\000\250\371\362\001\000\000\000\000\250\371\362\001\000\000\000\000\212\371\362\001\000\000\000\000P^\000\324\377\177", '\000' <repeats 23 times>, "\177\000\000`\362\065\001\000\000\000\000\003\000\316\000\000\000\000\000\330\370\315\000\000\000\000\000\004\000\000\200\377\177\000\000\060\325/\351\377\177\000\000\003\000\316\000\000\000\000\000\260\323/\351\377\177\000\000\310!\002\324\377\177\000\000\370&\002\324\377\177\000\000\330&\002\324\377\177\000\000\020\000\362\001\000\000\000\000\370&\002\324\377\177\000\000[I"
saved_cur_db_name =
cur_db_changed = false
_PRETTY_FUNCTION_ = "bool Prepared_statement::execute(String*, bool)"
error = true
stmt_db_name =
#9 0x0000000000622d90 in Prepared_statement::execute_loop (this=0x7fffd4005e50, expanded_query=0x7fffe92fd510, open_cursor=true, packet=0x1f2f98a "",
packet_end=0x1f2f9a8 "") at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_prepare.cc:3545
MAX_REPREPARE_ATTEMPTS = 3
_PRETTY_FUNCTION_ = "bool Prepared_statement::execute_loop(String*, bool, uchar*, uchar*)"
reprepare_observer =
error = false
reprepare_attempt = 0
need_set_parameters = false
#10 0x0000000000620d98 in mysqld_stmt_execute (thd=0x1f20010, packet_arg=0x1f2f981 "\001", packet_length=39)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_prepare.cc:2656
packet = 0x1f2f98a ""
flags = 1
expanded_query =
packet_end = 0x1f2f9a8 ""
stmt = 0x7fffd4005e50
open_cursor = true
stmt_id = 1
save_protocol = 0x1f205d8
db_stack_frame =
#11 0x0000000000601a7c in dispatch_command (command=COM_STMT_EXECUTE, thd=0x1f20010, packet=0x1f2f981 "\001", packet_length=39)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc:1009
net = 0x1f20320
_PRETTY_FUNCTION_ = "bool dispatch_command(enum_server_command, THD*, char*, uint)"
_FUNCTION_ = "dispatch_command"
error = false
db_stack_frame =
#12 0x0000000000600feb in do_command (thd=0x1f20010) at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc:794
return_value = false
packet = 0x1f2f980 "\027\001"
packet_length = 40
net = 0x1f20320
command = COM_STMT_EXECUTE
_PRETTY_FUNCTION_ = "bool do_command(THD*)"
db_stack_frame =
#13 0x00000000006f44f0 in do_handle_one_connection (thd_arg=0x1f20010) at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_connect.cc:1253
create_user = true
thd = 0x1f20010
#14 0x00000000006f3fc2 in handle_one_connection (arg=0x1f20010) at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_connect.cc:1168
thd = 0x1f20010
#15 0x00007ffff75a5f4a in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#16 0x00007ffff629afad in clone () from /lib64/libc.so.6
No symbol table info available.
>How-To-Repeat:
The query log shows these queries before sigabrt:ing (segfault from a non-debug build, at sql_cache.cc:1492):
CREATE TABLE IF NOT EXISTS events (scope_id INT(11) UNSIGNED NOT NULL,timestamp_id MEDIUMINT(11) UNSIGNED NOT NULL,key_id INT(11) UNSIGNED NOT NULL,value_id INT(11) UNSIGNED NOT NULL,data MEDIUMBLOB NOT NULL,PRIMARY KEY (scope_id, timestamp_id, key_id, value_id))
CREATE TABLE IF NOT EXISTS ids (id INT(11) UNSIGNED NOT NULL PRIMARY KEY,value VARCHAR(255) NOT NULL UNIQUE)
CREATE TABLE IF NOT EXISTS history (id INT(11) UNSIGNED NOT NULL AUTO_INCREMENT PRIMARY KEY,timestamp_id INT(11) NOT NULL,date TIMESTAMP DEFAULT CURRENT_TIMESTAMP)
SELECT timestamp_id FROM history ORDER BY id DESC LIMIT 1
SELECT value_id, len FROM (SELECT value_id, LENGTH(data) len FROM events WHERE scope_id = ? AND timestamp_id = ? AND key_id = ?) tbl ORDER BY 2 DESC LIMIT ?
SELECT value_id, len FROM (SELECT value_id, LENGTH(data) len FROM events WHERE scope_id = ? AND timestamp_id = ? AND key_id = ?) tbl ORDER BY 2 DESC LIMIT ?
SELECT value_id, len FROM (SELECT value_id, LENGTH(data) len FROM events WHERE scope_id = ? AND timestamp_id = ? AND key_id = ?) tbl ORDER BY 2 DESC LIMIT ?
The crash does not happen if we run it sequentially. We're using a ConnectionPool from libzdb (2.10.5), and it occurs every time. So far, we've reproduced this on linux 32 & 64 bit environments as well as Mac OS X Mountain Lion. Haven't tried MySQL 5.5 yet.
>Fix:
No fix as of yet (turn off query cache or don't run it in parallel)
Gliffy Diagrams
Attachments
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
Re: Crash in sql_cache.cc (mariadb 5.5.25)
We've put up a reproducible test case here: https://github.com/sydneystockholm/mariadb-bug-1039277
Re: Crash in sql_cache.cc (mariadb 5.5.25)
The crash could happen when using query cache, prepared statements combined with a read only cursor.
Temporary fix: Don't use mysql_stmt_attr_set(...CURSOR_TYPE_READ_ONLY)
Fix pushed into MariaDB 5.5 and it will appear in 5.5.27
Re: Crash in sql_cache.cc (mariadb 5.5.25)
After the fix (on revno 3499), the provided test doesn't cause the assertion failure anymore (on revno 3498 it does).
I am getting lots of 'aborted connection' warnings, and the test ends with an exception Connection_prepareStatement at src/db/Connection.c:315, but it happens regardless query cache, even before the patch, so I suppose it has nothing to do with this bug, and that's just how the test or the library works.
Re: Crash in sql_cache.cc (mariadb 5.5.25)
This is related to libzdb pooling behaviour rather than the bug - ConnectionPool_getConnection() returns NULL if a connection isn't available. I've updated the test case to account for this @ https://github.com/sydneystockholm/mariadb-bug-1039277/commit/c2b62b8f60a948b468e4f341a47c36ac7df601f6
Re: Crash in sql_cache.cc (mariadb 5.5.25)
With the above commit, we aren't able to reproduce this bug in the same environment. Thanks for fixing it so quickly.
Launchpad bug id: 1039277
Re: Crash in sql_cache.cc (mariadb 5.5.25)
A couple of notes:
1. This is reproduced against an empty table as well
{func = 0xcdbd5a "mysql_execute_command", file = 0xcdb6e0 "/var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc", level = 2147483653, prev = 0x7fffe9344da0}2. The CREATE TABLE queries doesn't affect the outcome
3. We rewrote the query to not do a subselect, and it still crashes. Here's the gdb stracktrace:
0 0x00007ffff61e9f55 in raise () from /lib64/libc.so.6
No symbol table info available.
#1 0x00007ffff61eb3d8 in abort () from /lib64/libc.so.6
No symbol table info available.
#2 0x00007ffff61e2f42 in ?? () from /lib64/libc.so.6
No symbol table info available.
#3 0x00007ffff61e2ff2 in __assert_fail () from /lib64/libc.so.6
No symbol table info available.
#4 0x00000000005bee14 in Query_cache::store_query (this=0x1495ce0, thd=0x1f22000, tables_used=0x7fffb8007bb0)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_cache.cc:1386
tot_length = 140737105905824
_PRETTY_FUNCTION_ = "void Query_cache::store_query(THD*, TABLE_LIST*)"
local_tables = 32513
query = 0x5a3d8a "\211\330H\203\304\070[]ÐUH\211\345H\203\354\060H\211}\370\211u\364\211U\360\211M\354L\211E\340L\211M\330H\213E\370\213U\364\211\020H\213E\370\213U\360\211P\004H\213E\370\213U\354\211P\bH\213E\370H\213U\340H\211P\020H\213E\370H\213U\330H\211P\030H\213E\370\306@ "
query_length = 140737105905856
tables_type = 0 '\000'
db_stack_frame =
#5 0x000000000060af7a in execute_sqlcom_select (thd=0x1f22000, all_tables=0x7fffb8007bb0)
{func = 0xce0003 "mysqld_stmt_execute", file = 0xcdf8d8 "/var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_prepare.cc", level = 2147483652, prev = 0x7fffe9345530}at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc:4620
lex = 0x7fffb8006698
result = 0x7fffb8003218
res = false
#6 0x00000000006044da in mysql_execute_command (thd=0x1f22000) at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc:2189
privileges_requested = 1
res = 0
lex = 0x7fffb8006698
db_stack_frame =
_FUNCTION_ = "mysql_execute_command"
{ str = 0xc60c8d "\311\303UH\211\345H\203\354PH\211}up_result = 0
_PRETTY_FUNCTION_ = "int mysql_execute_command(THD*)"
select_lex = 0x7fffb8006e20
first_table = 0x7fffb8007bb0
all_tables = 0x7fffb8007bb0
unit = 0x7fffb8006748
have_table_map_for_update = false
#7 0x00000000008db161 in mysql_open_cursor (thd=0x1f22000, result=0x7fffb8006348, pcursor=0x7fffb80063a8)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_cursor.cc:118
save_result = 0x7fffb80084b8
result_materialize = 0x7fffb8003218
lex = 0x7fffb8006698
rc = 0
#8 0x0000000000623bd8 in Prepared_statement::execute (this=0x7fffb8006290, expanded_query=0x7fffe9345510, open_cursor=true)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_prepare.cc:3869
stmt_backup = {<ilink> = {_vptr.ilink = 0xcd3950, prev = 0x0, next = 0x0}, <Query_arena> = {_vptr.Query_arena = 0xcd3980, free_list =
0x7fffe93452f0, mem_root = 0xc74389, is_backup_arena = false, is_reprepared = false, state = 32767}, id = 0,
mark_used_columns = MARK_COLUMNS_READ, name =
\310H\211u\300\211U\274H\215E\320H\211\301\272
{", length = 29682324272},
{str = 0x7fffb8003188 "SELECT id FROM ids WHERE value = 'path'", length = 39}lex = 0x1f242d8, query_string = {string =
, cs = 0x1491140},
{Ptr = 0x0, str_length = 0, Alloced_length = 0, extra_alloc = 0, alloced = false, str_charset = 0x135f260}base_query =
,
{str = 0x7fffe9345360 "0\n", length = 202}db = 0x7fffe93453b0 "", db_length = 140737105908592, query_cache_is_applicable = -98 '\236'}
old_stmt_arena = 0x1f22018
saved_cur_db_name_buf = "0\n\000\270\377\177\000\000\260S4\351\377\177\000\000@T4\351\377\177\000\000E\331a\000\000\000\000\000\360S4\351\377\177\000\000\020U4\351\377\177\000\000\063\275\362\001\000\000\000\000\063\275\362\001\000\000\000\000*\275\362\001\000\000\000\000\220b\000\270\377\177", '\000' <repeats 23 times>, "\177\000\000`\362\065\001\000\000\000\000\003\000\316\000\000\000\000\000\330\370\315\000\000\000\000\000\004\000\000\200\377\177\000\000\060U4\351\377\177\000\000\003\000\316\000\000\000\000\000\260S4\351\377\177\000\000(\207\000\270\377\177\000\000\270\204\000\270\377\177\000\000\260\204\000\270\377\177\000\000\000 \362\001\000\000\000\000\270\204\000\270\377\177\000\000[I"
saved_cur_db_name =
cur_db_changed = false
{str = 0x7fffb8007990 "juliette", length = 8}_PRETTY_FUNCTION_ = "bool Prepared_statement::execute(String*, bool)"
error = true
stmt_db_name =
#9 0x0000000000622d90 in Prepared_statement::execute_loop (this=0x7fffb8006290, expanded_query=0x7fffe9345510, open_cursor=true,
{m_invalidated = false}packet=0x1f2bd2a "", packet_end=0x1f2bd33 "") at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_prepare.cc:3545
MAX_REPREPARE_ATTEMPTS = 3
_PRETTY_FUNCTION_ = "bool Prepared_statement::execute_loop(String*, bool, uchar*, uchar*)"
reprepare_observer =
error = false
{Ptr = 0x7fffb8000af0 "SELECT id FROM ids WHERE value = 'path'", str_length = 39, Alloced_length = 40, extra_alloc = 0, alloced = true, str_charset = 0x1491140}reprepare_attempt = 0
need_set_parameters = false
#10 0x0000000000620d98 in mysqld_stmt_execute (thd=0x1f22000, packet_arg=0x1f2bd21 "\001", packet_length=18)
at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_prepare.cc:2656
packet = 0x1f2bd2a ""
flags = 1
expanded_query =
packet_end = 0x1f2bd33 ""
{func = 0xcdb899 "dispatch_command", file = 0xcdb6e0 "/var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc", level = 2147483651, prev = 0x7fffe93456c0}stmt = 0x7fffb8006290
open_cursor = true
stmt_id = 1
save_protocol = 0x1f225c8
db_stack_frame =
#11 0x0000000000601a7c in dispatch_command (command=COM_STMT_EXECUTE, thd=0x1f22000, packet=0x1f2bd21 "\001", packet_length=18)
{func = 0xcdb7e4 "do_command", file = 0xcdb6e0 "/var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc", level = 2147483650, prev = 0x7fffe9345e30}at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc:1009
net = 0x1f22310
_PRETTY_FUNCTION_ = "bool dispatch_command(enum_server_command, THD*, char*, uint)"
_FUNCTION_ = "dispatch_command"
error = false
db_stack_frame =
#12 0x0000000000600feb in do_command (thd=0x1f22000) at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc:794
{func = 0xeccf05 "?func", file = 0xeccf0b "?file", level = 2147483649, prev = 0x0}return_value = false
packet = 0x1f2bd20 "\027\001"
packet_length = 19
net = 0x1f22310
command = COM_STMT_EXECUTE
_PRETTY_FUNCTION_ = "bool do_command(THD*)"
db_stack_frame =
#13 0x00000000006f44f0 in do_handle_one_connection (thd_arg=0x1f22000) at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_connect.cc:1253
create_user = true
thd = 0x1f22000
#14 0x00000000006f3fc2 in handle_one_connection (arg=0x1f22000) at /var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_connect.cc:1168
thd = 0x1f22000
#15 0x00007ffff75a5f4a in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#16 0x00007ffff629afad in clone () from /lib64/libc.so.6
No symbol table info available.