Crash in sql_cache.cc (mariadb 5.5.25)

[jbergstroem]

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_ = {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 = 0x7fffe92fcda0}
#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_ = {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 = 0x7fffe92fd530}
        __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 = {
            str = 0xc60c8d "\311\303UH\211\345H\203\354PH\211}\310H\211u\300\211U\274H\215E\320H\211\301\272{", length = 8610247264}, lex = 0x1f222e8,
          query_string = {string = {
              str = 0x7fffd4019958 "SELECT value_id, len FROM (SELECT value_id, LENGTH(data) len FROM events WHERE scope_id = 4 AND timestamp_id = 0 AND key_id = 395871952) tbl ORDER BY 2 DESC LIMIT 24", length = 165}, 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 = {str = 0x7fffe92fd360 "\220W", length = 202}
        cur_db_changed = false
        __PRETTY_FUNCTION__ = "bool Prepared_statement::execute(String*, bool)"
        error = true
        stmt_db_name = {str = 0x7fffd401dd70 "juliette", length = 8}
#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 = {m_invalidated = false}
        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 = {
          Ptr = 0x7fffd4000920 "SELECT value_id, len FROM (SELECT value_id, LENGTH(data) len FROM events WHERE scope_id = 4 AND timestamp_id = 0 AND key_id = 395871952) tbl ORDER BY 2 DESC LIMIT 24", str_length = 165, Alloced_length = 296, extra_alloc = 128, alloced = true, str_charset = 0x1491140}
        packet_end = 0x1f2f9a8 ""
        stmt = 0x7fffd4005e50
        open_cursor = true
        stmt_id = 1
        save_protocol = 0x1f205d8
        _db_stack_frame_ = {func = 0xcdb899 "dispatch_command", file = 0xcdb6e0 "/var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc",
          level = 2147483651, prev = 0x7fffe92fd6c0}
#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_ = {func = 0xcdb7e4 "do_command", file = 0xcdb6e0 "/var/tmp/portage/dev-db/mariadb-5.5.25/work/mysql/sql/sql_parse.cc", level = 2147483650,
          prev = 0x7fffe92fde30}
#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_ = {func = 0xeccf05 "?func", file = 0xeccf0b "?file", level = 2147483649, prev = 0x0}
#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)

[jbergstroem (bugs-bergstroem-deactivatedaccount)]

A couple of notes:

1. This is reproduced against an empty table as well
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_ = {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}
#5 0x000000000060af7a in execute_sqlcom_select (thd=0x1f22000, all_tables=0x7fffb8007bb0)
    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_ = {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}
        __FUNCTION__ = "mysql_execute_command"
        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 = ...

[jbergstroem (bugs-bergstroem-deactivatedaccount)]

We've put up a reproducible test case here: https://github.com/sydneystockholm/mariadb-bug-1039277

[Michael Widenius (monty)]

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

[Elena Stepanova (elenst)]

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.

[Chris O'Hara (9e9o1ko8b2f5xpiibgscjzl-18krw-0zxvj9hhx1hzo5xiyhxz186)]

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

[jbergstroem (bugs-bergstroem-deactivatedaccount)]

With the above commit, we aren't able to reproduce this bug in the same environment. Thanks for fixing it so quickly.